aboutsummaryrefslogtreecommitdiff
diff options
context:
space:
mode:
Diffstat
-rw-r--r--ca/tests/smoketest.py14
-rw-r--r--ca/tests/testpoke.py1
-rw-r--r--ca/tests/yamlconf.py3
-rw-r--r--ca/tests/yamltest.py3
-rw-r--r--rpki/async.py3
-rw-r--r--rpki/http.py137
-rw-r--r--rpki/irdbd.py4
-rw-r--r--rpki/left_right.py4
-rw-r--r--rpki/log.py96
-rw-r--r--rpki/old_irdbd.py10
-rw-r--r--rpki/pubd.py4
-rw-r--r--rpki/publication.py2
-rw-r--r--rpki/rootd.py8
-rw-r--r--rpki/rpkid.py7
-rw-r--r--rpki/rpkid_tasks.py55
-rw-r--r--rpki/up_down.py2
16 files changed, 145 insertions, 208 deletions
diff --git a/ca/tests/smoketest.py b/ca/tests/smoketest.py
index 87927a81..1f0215f2 100644
--- a/ca/tests/smoketest.py
+++ b/ca/tests/smoketest.py
@@ -159,7 +159,7 @@ def main():
Main program.
"""
- rpki.log.init(smoketest_name)
+ rpki.log.init(smoketest_name, argparse.Namespace(log_level = logging.DEBUG, log_stream = sys.stdout))
logger.info("Starting")
pubd_process = None
@@ -299,12 +299,9 @@ def main():
logger.info("Event loop exited normally")
except Exception, e:
-
- logger.info("Event loop exited with an exception: %r" % e)
- rpki.log.traceback(logger)
+ logger.exception("Event loop exited with an exception")
finally:
-
logger.info("Cleaning up")
for a in db.engines:
a.kill_daemons()
@@ -631,7 +628,7 @@ class allocation(object):
def done(e):
if isinstance(e, Exception):
- rpki.log.traceback(logger)
+ logger.exception("Exception while rekeying %s", self.name)
raise e
cb()
@@ -648,7 +645,7 @@ class allocation(object):
def done(e):
if isinstance(e, Exception):
- rpki.log.traceback(logger)
+ logger.exception("Exception while revoking %s", self.name)
raise e
cb()
@@ -1295,8 +1292,7 @@ def call_pubd(pdus, cb):
cb(r_msg)
def call_pubd_eb(e):
- logger.warning("Problem calling pubd: %s" % e)
- rpki.log.traceback(logger)
+ logger.exception("Problem calling pubd")
rpki.http.client(
url = q_url,
diff --git a/ca/tests/testpoke.py b/ca/tests/testpoke.py
index bf1e1e43..9ca03dce 100644
--- a/ca/tests/testpoke.py
+++ b/ca/tests/testpoke.py
@@ -130,7 +130,6 @@ def do_revoke():
dispatch = { "list" : do_list, "issue" : do_issue, "revoke" : do_revoke }
def fail(e): # pylint: disable=W0621
- rpki.log.traceback(logger, args.debug)
sys.exit("Testpoke failed: %s" % e)
cms_ta = get_PEM("cms-ca-cert", rpki.x509.X509)
diff --git a/ca/tests/yamlconf.py b/ca/tests/yamlconf.py
index 56bec483..7b737836 100644
--- a/ca/tests/yamlconf.py
+++ b/ca/tests/yamlconf.py
@@ -34,6 +34,7 @@ import os
import sys
import yaml
import time
+import logging
import argparse
import subprocess
import lxml.etree
@@ -672,7 +673,7 @@ def main():
quiet = args.quiet
yaml_file = args.yaml_file
- rpki.log.init("yamlconf")
+ rpki.log.init("yamlconf", argparse.Namespace(log_level = logging.DEBUG, log_stream = sys.stdout))
# Allow optional config file for this tool to override default
# passwords: this is mostly so that I can show a complete working
diff --git a/ca/tests/yamltest.py b/ca/tests/yamltest.py
index f8be9c65..df60ec17 100644
--- a/ca/tests/yamltest.py
+++ b/ca/tests/yamltest.py
@@ -41,6 +41,7 @@ and waits for one of them to exit.
import subprocess
import re
import os
+import logging
import argparse
import sys
import yaml
@@ -665,7 +666,7 @@ try:
if args.pidfile is not None:
open(args.pidfile, "w").write("%s\n" % os.getpid())
- rpki.log.init("yamltest")
+ rpki.log.init("yamltest", argparse.Namespace(log_level = logging.DEBUG, log_stream = sys.stdout))
# Allow optional config file for this tool to override default
# passwords: this is mostly so that I can show a complete working
diff --git a/rpki/async.py b/rpki/async.py
index 012d8f06..a0fbe3ef 100644
--- a/rpki/async.py
+++ b/rpki/async.py
@@ -218,8 +218,7 @@ class timer(object):
if t.errback is not None:
t.errback(e)
else:
- logger.error("Unhandled exception from timer %r: %s" % (t, e))
- rpki.log.traceback(logger)
+ logger.exception("Unhandled exception from timer %r", t)
def __repr__(self):
return rpki.log.log_repr(self, self.when, repr(self.handler))
diff --git a/rpki/http.py b/rpki/http.py
index 64af0d4d..7127bbde 100644
--- a/rpki/http.py
+++ b/rpki/http.py
@@ -282,26 +282,6 @@ class http_response(http_message):
def __repr__(self):
return rpki.log.log_repr(self, self.code, self.reason)
-# This probably ought to be using logging.LoggerAdapter or some such,
-# and the level check should be converted to whatever the natural
-# thing is with the logging package, but for now just preserve the old
-# structure for now while transitioning from our homegrown logging
-# code to Python logging package.
-#
-# So it turns out that, as used in the current code, all invocations
-# of this are either with the default logging.DEBUG or with
-# logging.WARNING, we don't use any other settings. This suggets that
-# we could clean up this mess and get rid of the extra argument just
-# by providing two methods instead of one, assuming that the
-# LoggingAdapter doesn't just solve the whole problem for us.
-
-def log_method(self, msg, level = logging.DEBUG):
- """
- Logging method used in several different classes.
- """
- if debug_http or level > logging.DEBUG:
- logging.log(level, "%r: %s", self, msg)
-
def addr_to_string(addr):
"""
Convert socket addr tuple to printable string. Assumes 2-element
@@ -320,8 +300,6 @@ class http_stream(asynchat.async_chat):
Virtual class representing an HTTP message stream.
"""
- log = log_method
-
def __repr__(self):
status = ["connected"] if self.connected else []
try:
@@ -331,6 +309,7 @@ class http_stream(asynchat.async_chat):
return rpki.log.log_repr(self, *status)
def __init__(self, sock = None):
+ self.logger = logging.LoggerAdapter(logger, dict(context = self))
asynchat.async_chat.__init__(self, sock)
self.buffer = []
self.timer = rpki.async.timer(self.handle_timeout)
@@ -352,10 +331,10 @@ class http_stream(asynchat.async_chat):
it.
"""
if self.timeout is not None:
- self.log("Setting timeout %s" % self.timeout)
+ self.logger.debug("Setting timeout %s" % self.timeout)
self.timer.set(self.timeout)
else:
- self.log("Clearing timeout")
+ self.logger.debug("Clearing timeout")
self.timer.cancel()
def collect_incoming_data(self, data):
@@ -414,7 +393,7 @@ class http_stream(asynchat.async_chat):
the process of exiting the chunk decoder.
"""
n = int(self.get_buffer().partition(";")[0], 16)
- self.log("Chunk length %s" % n)
+ self.logger.debug("Chunk length %s" % n)
if n:
self.chunk_handler = self.chunk_body
self.set_terminator(n)
@@ -428,7 +407,7 @@ class http_stream(asynchat.async_chat):
body of a chunked message (sic). Save it, and prepare to move on
to the next chunk.
"""
- self.log("Chunk body")
+ self.logger.debug("Chunk body")
self.msg.body += self.buffer
self.buffer = []
self.chunk_handler = self.chunk_discard_crlf
@@ -439,7 +418,7 @@ class http_stream(asynchat.async_chat):
Consume the CRLF that terminates a chunk, reinitialize chunk
decoder to be ready for the next chunk.
"""
- self.log("Chunk CRLF")
+ self.logger.debug("Chunk CRLF")
s = self.get_buffer()
assert s == "", "%r: Expected chunk CRLF, got '%s'" % (self, s)
self.chunk_handler = self.chunk_header
@@ -449,7 +428,7 @@ class http_stream(asynchat.async_chat):
Consume chunk trailer, which should be empty, then (finally!) exit
the chunk decoder and hand complete message off to the application.
"""
- self.log("Chunk trailer")
+ self.logger.debug("Chunk trailer")
s = self.get_buffer()
assert s == "", "%r: Expected end of chunk trailers, got '%s'" % (self, s)
self.chunk_handler = None
@@ -472,16 +451,15 @@ class http_stream(asynchat.async_chat):
etype = sys.exc_info()[0]
if etype in (SystemExit, rpki.async.ExitNow):
raise
- rpki.log.traceback(logger)
if etype is not rpki.exceptions.HTTPClientAborted:
- self.log("Closing due to error", logging.WARNING)
+ self.logger.exception("Closing due to error")
self.close()
def handle_timeout(self):
"""
Inactivity timer expired, close connection with prejudice.
"""
- self.log("Timeout, closing")
+ self.logger.debug("Timeout, closing")
self.close()
def handle_close(self):
@@ -489,7 +467,7 @@ class http_stream(asynchat.async_chat):
Wrapper around asynchat connection close handler, so that we can
log the event, cancel timer, and so forth.
"""
- self.log("Close event in HTTP stream handler")
+ self.logger.debug("Close event in HTTP stream handler")
self.timer.cancel()
asynchat.async_chat.handle_close(self)
@@ -510,7 +488,7 @@ class http_server(http_stream):
self.handlers = handlers
http_stream.__init__(self, sock = sock)
self.expect_close = not want_persistent_server
- self.log("Starting")
+ self.logger.debug("Starting")
def handle_no_content_length(self):
"""
@@ -536,7 +514,7 @@ class http_server(http_stream):
Content-Type, look for a handler, and if everything looks right,
pass the message body, path, and a reply callback to the handler.
"""
- self.log("Received request %r" % self.msg)
+ self.logger.debug("Received request %r" % self.msg)
if not self.msg.persistent:
self.expect_close = True
handler = self.find_handler(self.msg.path)
@@ -553,7 +531,7 @@ class http_server(http_stream):
except (rpki.async.ExitNow, SystemExit):
raise
except Exception, e:
- rpki.log.traceback(logger)
+ self.logger.exception("Unhandled exception while handling HTTP request")
self.send_error(500, reason = "Unhandled exception %s: %s" % (e.__class__.__name__, e))
else:
self.send_error(code = error[0], reason = error[1])
@@ -577,7 +555,7 @@ class http_server(http_stream):
listen for next message; otherwise, queue up a close event for
this stream so it will shut down once the reply has been sent.
"""
- self.log("Sending response %s %s" % (code, reason))
+ self.logger.debug("Sending response %s %s" % (code, reason))
if code >= 400:
self.expect_close = True
msg = http_response(code = code, reason = reason, body = body,
@@ -585,11 +563,11 @@ class http_server(http_stream):
Connection = "Close" if self.expect_close else "Keep-Alive")
self.push(msg.format())
if self.expect_close:
- self.log("Closing")
+ self.logger.debug("Closing")
self.timer.cancel()
self.close_when_done()
else:
- self.log("Listening for next message")
+ self.logger.debug("Listening for next message")
self.restart()
class http_listener(asyncore.dispatcher):
@@ -597,8 +575,6 @@ class http_listener(asyncore.dispatcher):
Listener for incoming HTTP connections.
"""
- log = log_method
-
def __repr__(self):
try:
status = (addr_to_string(self.addr),)
@@ -607,6 +583,7 @@ class http_listener(asyncore.dispatcher):
return rpki.log.log_repr(self, *status)
def __init__(self, handlers, addrinfo):
+ self.logger = logging.LoggerAdapter(logger, dict(context = self))
asyncore.dispatcher.__init__(self)
self.handlers = handlers
try:
@@ -622,11 +599,10 @@ class http_listener(asyncore.dispatcher):
self.bind(sockaddr)
self.listen(5)
except Exception, e:
- self.log("Couldn't set up HTTP listener: %s" % e, logging.WARNING)
- rpki.log.traceback(logger)
+ self.logger.exception("Couldn't set up HTTP listener")
self.close()
for h in handlers:
- self.log("Handling %s" % h[0])
+ self.logger.debug("Handling %s" % h[0])
def handle_accept(self):
"""
@@ -635,12 +611,12 @@ class http_listener(asyncore.dispatcher):
"""
try:
s, c = self.accept()
- self.log("Accepting connection from %s" % addr_to_string(c))
+ self.logger.debug("Accepting connection from %s" % addr_to_string(c))
http_server(sock = s, handlers = self.handlers)
except (rpki.async.ExitNow, SystemExit):
raise
except Exception, e:
- self.log("Unable to accept connection: %s" % e)
+ self.logger.debug("Unable to accept connection: %s" % e)
self.handle_error()
def handle_error(self):
@@ -649,8 +625,7 @@ class http_listener(asyncore.dispatcher):
"""
if sys.exc_info()[0] in (SystemExit, rpki.async.ExitNow):
raise
- self.log("Error in HTTP listener", logging.WARNING)
- rpki.log.traceback(logger)
+ self.logger.exception("Error in HTTP listener")
class http_client(http_stream):
"""
@@ -670,8 +645,8 @@ class http_client(http_stream):
state = None
def __init__(self, queue, hostport):
- self.log("Creating new connection to %s" % addr_to_string(hostport))
http_stream.__init__(self)
+ self.logger.debug("Creating new connection to %s" % addr_to_string(hostport))
self.queue = queue
self.host = hostport[0]
self.port = hostport[1]
@@ -683,14 +658,14 @@ class http_client(http_stream):
Create socket and request a connection.
"""
if not use_adns:
- self.log("Not using ADNS")
+ self.logger.debug("Not using ADNS")
self.gotaddrinfo([(socket.AF_INET, self.host)])
elif self.host == "localhost":
- self.log("Bypassing DNS for localhost")
+ self.logger.debug("Bypassing DNS for localhost")
self.gotaddrinfo(localhost_addrinfo())
else:
families = supported_address_families(enable_ipv6_clients)
- self.log("Starting ADNS lookup for %s in families %r" % (self.host, families))
+ self.logger.debug("Starting ADNS lookup for %s in families %r" % (self.host, families))
rpki.adns.getaddrinfo(self.gotaddrinfo, self.dns_error, self.host, families)
def dns_error(self, e):
@@ -706,7 +681,7 @@ class http_client(http_stream):
"""
try:
self.af, self.address = random.choice(addrinfo)
- self.log("Connecting to AF %s host %s port %s addr %s" % (self.af, self.host, self.port, self.address))
+ self.logger.debug("Connecting to AF %s host %s port %s addr %s" % (self.af, self.host, self.port, self.address))
self.create_socket(self.af, socket.SOCK_STREAM)
self.connect((self.address, self.port))
if self.addr is None:
@@ -721,7 +696,7 @@ class http_client(http_stream):
"""
Asyncore says socket has connected.
"""
- self.log("Socket connected")
+ self.logger.debug("Socket connected")
self.set_state("idle")
assert self.queue.client is self
self.queue.send_request()
@@ -730,7 +705,7 @@ class http_client(http_stream):
"""
Set HTTP client connection state.
"""
- self.log("State transition %s => %s" % (self.state, state))
+ self.logger.debug("State transition %s => %s" % (self.state, state))
self.state = state
def handle_no_content_length(self):
@@ -746,7 +721,7 @@ class http_client(http_stream):
"""
Queue up request message and kickstart connection.
"""
- self.log("Sending request %r" % msg)
+ self.logger.debug("Sending request %r" % msg)
assert self.state == "idle", "%r: state should be idle, is %s" % (self, self.state)
self.set_state("request-sent")
msg.headers["Connection"] = "Close" if self.expect_close else "Keep-Alive"
@@ -763,7 +738,7 @@ class http_client(http_stream):
arrange for the stream to shut down.
"""
- self.log("Message received, state %s" % self.state)
+ self.logger.debug("Message received, state %s" % self.state)
if not self.msg.persistent:
self.expect_close = True
@@ -771,16 +746,16 @@ class http_client(http_stream):
if self.state != "request-sent":
if self.state == "closing":
assert not self.msg.body
- self.log("Ignoring empty response received while closing")
+ self.logger.debug("Ignoring empty response received while closing")
return
raise rpki.exceptions.HTTPUnexpectedState, "%r received message while in unexpected state %s" % (self, self.state)
if self.expect_close:
- self.log("Closing")
+ self.logger.debug("Closing")
self.set_state("closing")
self.close_when_done()
else:
- self.log("Idling")
+ self.logger.debug("Idling")
self.set_state("idle")
self.update_timeout()
@@ -803,7 +778,7 @@ class http_client(http_stream):
sent, signal the error.
"""
http_stream.handle_close(self)
- self.log("State %s" % self.state)
+ self.logger.debug("State %s" % self.state)
if self.get_terminator() is None:
self.handle_body()
elif self.state == "request-sent":
@@ -818,7 +793,7 @@ class http_client(http_stream):
"""
bad = self.state not in ("idle", "closing")
if bad:
- self.log("Timeout while in state %s" % self.state, logging.WARNING)
+ self.logger.warning("Timeout while in state %s" % self.state)
http_stream.handle_timeout(self)
if bad:
try:
@@ -834,7 +809,7 @@ class http_client(http_stream):
down the connection and pass back the exception.
"""
eclass, edata = sys.exc_info()[0:2]
- self.log("Error on HTTP client connection %s:%s %s %s" % (self.host, self.port, eclass, edata), logging.WARNING)
+ self.logger.warning("Error on HTTP client connection %s:%s %s %s" % (self.host, self.port, eclass, edata))
http_stream.handle_error(self)
self.queue.return_result(self, edata, detach = True)
@@ -845,22 +820,21 @@ class http_queue(object):
stream itself, this class provides a slightly higher-level API.
"""
- log = log_method
-
def __repr__(self):
return rpki.log.log_repr(self, addr_to_string(self.hostport))
def __init__(self, hostport):
+ self.logger = logging.LoggerAdapter(logger, dict(context = self))
self.hostport = hostport
self.client = None
- self.log("Created")
+ self.logger.debug("Created")
self.queue = []
def request(self, *requests):
"""
Append http_request object(s) to this queue.
"""
- self.log("Adding requests %r" % requests)
+ self.logger.debug("Adding requests %r" % requests)
self.queue.extend(requests)
def restart(self):
@@ -875,13 +849,13 @@ class http_queue(object):
try:
if self.client is None:
self.client = http_client(self, self.hostport)
- self.log("Attached client %r" % self.client)
+ self.logger.debug("Attached client %r" % self.client)
self.client.start()
elif self.client.state == "idle":
- self.log("Sending request to existing client %r" % self.client)
+ self.logger.debug("Sending request to existing client %r" % self.client)
self.send_request()
else:
- self.log("Client %r exists in state %r" % (self.client, self.client.state))
+ self.logger.debug("Client %r exists in state %r" % (self.client, self.client.state))
except (rpki.async.ExitNow, SystemExit):
raise
except Exception, e:
@@ -902,7 +876,7 @@ class http_queue(object):
conditions.
"""
if client_ is self.client:
- self.log("Detaching client %r" % client_)
+ self.logger.debug("Detaching client %r" % client_)
self.client = None
def return_result(self, client, result, detach = False): # pylint: disable=W0621
@@ -914,7 +888,7 @@ class http_queue(object):
"""
if client is not self.client:
- self.log("Wrong client trying to return result. THIS SHOULD NOT HAPPEN. Dropping result %r" % result, logging.WARNING)
+ self.logger.warning("Wrong client trying to return result. THIS SHOULD NOT HAPPEN. Dropping result %r" % result)
return
if detach:
@@ -922,16 +896,16 @@ class http_queue(object):
try:
req = self.queue.pop(0)
- self.log("Dequeuing request %r" % req)
+ self.logger.debug("Dequeuing request %r" % req)
except IndexError:
- self.log("No caller. THIS SHOULD NOT HAPPEN. Dropping result %r" % result, logging.WARNING)
+ self.logger.warning("No caller. THIS SHOULD NOT HAPPEN. Dropping result %r" % result)
return
assert isinstance(result, http_response) or isinstance(result, Exception)
if isinstance(result, http_response):
try:
- self.log("Returning result %r to caller" % result)
+ self.logger.debug("Returning result %r to caller" % result)
req.callback(result.body)
except (rpki.async.ExitNow, SystemExit):
raise
@@ -940,21 +914,14 @@ class http_queue(object):
if isinstance(result, Exception):
try:
- self.log("Returning exception %r to caller: %s" % (result, result), logging.WARNING)
+ self.logger.warning("Returning exception %r to caller: %s" % (result, result))
req.errback(result)
except (rpki.async.ExitNow, SystemExit):
raise
except Exception:
- #
- # If we get here, we may have lost the event chain. Not
- # obvious what we can do about it at this point, but force a
- # traceback so that it will be somewhat obvious that something
- # really bad happened.
- #
- self.log("Exception in exception callback", logging.WARNING)
- rpki.log.traceback(logger, True)
-
- self.log("Queue: %r" % self.queue)
+ self.logger.exception("Exception in exception callback, may have lost event chain")
+
+ self.logger.debug("Queue: %r" % self.queue)
if self.queue:
self.restart()
diff --git a/rpki/irdbd.py b/rpki/irdbd.py
index 02d90609..430da4c2 100644
--- a/rpki/irdbd.py
+++ b/rpki/irdbd.py
@@ -125,7 +125,7 @@ class main(object):
except (rpki.async.ExitNow, SystemExit):
raise
except Exception, e:
- rpki.log.traceback(logger)
+ logger.exception("Exception while handling HTTP request")
if q_pdu is None:
r_msg.append(rpki.left_right.report_error_elt.from_exception(e))
else:
@@ -135,7 +135,7 @@ class main(object):
except (rpki.async.ExitNow, SystemExit):
raise
except Exception, e:
- rpki.log.traceback(logger)
+ logger.exception("Unhandled exception while processing HTTP request")
cb(500, reason = "Unhandled exception %s: %s" % (e.__class__.__name__, e))
def dispatch(self, q_pdu, r_msg):
diff --git a/rpki/left_right.py b/rpki/left_right.py
index 69a06c09..ac849915 100644
--- a/rpki/left_right.py
+++ b/rpki/left_right.py
@@ -969,7 +969,7 @@ class child_elt(data_elt):
except rpki.exceptions.NoActiveCA, data:
done(q_msg.serve_error(data))
except Exception, e:
- rpki.log.traceback(logger)
+ logger.exception("Unhandled exception serving up-down request from %r", self)
done(q_msg.serve_error(e))
class list_resources_elt(rpki.xml_utils.base_elt, left_right_namespace):
@@ -1253,7 +1253,7 @@ class msg(rpki.xml_utils.msg, left_right_namespace):
def fail(e):
if not isinstance(e, rpki.exceptions.NotFound):
- rpki.log.traceback(logger)
+ logger.exception("Unhandled exception serving left-right PDU %r", q_pdu)
r_msg.append(report_error_elt.from_exception(
e, self_handle = q_pdu.self_handle, tag = q_pdu.tag))
cb(r_msg)
diff --git a/rpki/log.py b/rpki/log.py
index 2d13a953..77749c5a 100644
--- a/rpki/log.py
+++ b/rpki/log.py
@@ -65,6 +65,51 @@ use_setproctitle = True
proctitle_extra = os.path.basename(os.getcwd())
+
+class Formatter(object):
+ """
+ Reimplementation (easier than subclassing in this case) of
+ logging.Formatter.
+
+ It turns out that the logging code only cares about this class's
+ .format(record) method, everything else is internal; so long as
+ .format() converts a record into a properly formatted string, the
+ logging code is happy.
+
+ So, rather than mess around with dynamically constructing and
+ deconstructing and tweaking format strings and ten zillion options
+ we don't use, we just provide our own implementation that supports
+ what we do need.
+ """
+
+ converter = time.gmtime
+
+ def __init__(self, ident, handler):
+ self.ident = ident
+ self.is_syslog = isinstance(handler, logging.handlers.SysLogHandler)
+
+ def format(self, record):
+ return "".join(self.coformat(record)).rstrip("\n")
+
+ def coformat(self, record):
+ if not self.is_syslog:
+ yield time.strftime("%Y-%m-%d %H:%M:%S ", time.gmtime(record.created))
+ yield "%s[%d]: " % (self.ident, record.process)
+ try:
+ yield repr(record.context) + " "
+ except AttributeError:
+ pass
+ yield record.getMessage()
+ if record.exc_info:
+ if self.is_syslog or not enable_tracebacks:
+ lines = tb.format_exception_only(record.exc_info[0], record.exc_info[1])
+ lines.insert(0, ": ")
+ else:
+ lines = tb.format_exception(record.exc_info[0], record.exc_info[1], record.exc_info[2])
+ lines.insert(0, "\n")
+ for line in lines:
+ yield line
+
def argparse_setup(parser):
"""
Set up argparse stuff for functionality in this module.
@@ -109,7 +154,7 @@ def argparse_setup(parser):
help = "send logging to timed rotating file")
-def init(ident = "rpki", args = argparse.Namespace(log_level = logging.DEBUG, log_stream = sys.stderr)):
+def init(ident = "rpki", args = argparse.Namespace(log_level = logging.WARNING, log_stream = sys.stderr)):
"""
Initialize logging system.
@@ -143,18 +188,8 @@ def init(ident = "rpki", args = argparse.Namespace(log_level = logging.DEBUG, lo
else:
raise ValueError
-
- format = ident + "[%(process)d]: %(message)s"
- if not isinstance(handler, logging.handlers.SysLogHandler):
- format = "%(asctime)s " + format
-
- # At some point we will probably want our own subclass of
- # logging.Formatter so we can support LoggingAdapters with extra
- # fields, but this suffices for the moment.
- formatter = logging.Formatter(format, "%Y-%m-%d %H:%M:%S")
- formatter.converter = time.gmtime
- handler.setFormatter(formatter)
+ handler.setFormatter(Formatter(ident, handler))
root_logger = logging.getLogger()
root_logger.addHandler(handler)
@@ -167,43 +202,6 @@ def init(ident = "rpki", args = argparse.Namespace(log_level = logging.DEBUG, lo
setproctitle.setproctitle(ident)
-def traceback(trace_logger, do_it = None):
- """
- Consolidated backtrace facility with a bit of extra info. Argument
- specifies whether or not to log the traceback (some modules and
- classes have their own controls for this, this lets us provide a
- unified interface). If no argument is specified, we use the global
- default value rpki.log.enable_tracebacks.
-
- Assertion failures generate backtraces unconditionally, on the
- 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.
-
- logging.exception() doesn't do quite what we want here, or we'd just
- use that. In particular, logging.exception() puts the entire
- traceback (or, rather, the portion that it choses to print) into a
- single log message, and is pretty much tied to that model because
- its getting the exception data from one log record. This doesn't
- work well with syslog, which has a maximum record size. Maybe the
- real answer here is just that we shouldn't attempt to backtrace when
- logging via syslog, but, for now, keep using our old hack.
- """
-
- if do_it is None:
- do_it = enable_tracebacks
-
- e = sys.exc_info()[1]
- assert e is not None, "rpki.log.traceback() called without valid trace on stack! This should not happen."
-
- if do_it or isinstance(e, AssertionError):
- bt = tb.extract_stack(limit = 3)
- trace_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():
- trace_logger.warning(line)
-
def log_repr(obj, *tokens):
"""
Constructor for __repr__() strings, handles suppression of Python
diff --git a/rpki/old_irdbd.py b/rpki/old_irdbd.py
index 953d951d..8772e5b6 100644
--- a/rpki/old_irdbd.py
+++ b/rpki/old_irdbd.py
@@ -256,14 +256,14 @@ class main(object):
raise
except Exception, e:
- rpki.log.traceback(logger)
+ logger.exception("Exception serving PDU %r", q_pdu)
r_msg.append(rpki.left_right.report_error_elt.from_exception(e, q_pdu.self_handle, q_pdu.tag))
except (rpki.async.ExitNow, SystemExit):
raise
except Exception, e:
- rpki.log.traceback(logger)
+ logger.exception("Exception decoding query")
r_msg.append(rpki.left_right.report_error_elt.from_exception(e))
cb(200, body = rpki.left_right.cms_msg().wrap(r_msg, self.irdbd_key, self.irdbd_cert))
@@ -272,11 +272,7 @@ class main(object):
raise
except Exception, e:
- rpki.log.traceback(logger)
-
- # We only get here in cases where we couldn't or wouldn't generate
- # <report_error/>, so just return HTTP failure.
-
+ logger.exception("Unhandled exception, returning HTTP failure")
cb(500, reason = "Unhandled exception %s: %s" % (e.__class__.__name__, e))
diff --git a/rpki/pubd.py b/rpki/pubd.py
index 5a345c4d..e3498a27 100644
--- a/rpki/pubd.py
+++ b/rpki/pubd.py
@@ -142,7 +142,7 @@ class main(object):
except (rpki.async.ExitNow, SystemExit):
raise
except Exception, e:
- rpki.log.traceback(logger)
+ logger.exception("Unhandled exception processing control query, path %r", path)
cb(500, reason = "Unhandled exception %s: %s" % (e.__class__.__name__, e))
client_url_regexp = re.compile("/client/([-A-Z0-9_/]+)$", re.I)
@@ -170,5 +170,5 @@ class main(object):
except (rpki.async.ExitNow, SystemExit):
raise
except Exception, e:
- rpki.log.traceback(logger)
+ logger.exception("Unhandled exception processing client query, path %r", path)
cb(500, reason = "Could not process PDU: %s" % e)
diff --git a/rpki/publication.py b/rpki/publication.py
index 59650548..0efb0d76 100644
--- a/rpki/publication.py
+++ b/rpki/publication.py
@@ -432,7 +432,7 @@ class msg(rpki.xml_utils.msg, publication_namespace):
def fail(e):
if not isinstance(e, rpki.exceptions.NotFound):
- rpki.log.traceback(logger)
+ logger.exception("Exception processing PDU %r", q_pdu)
r_msg.append(report_error_elt.from_exception(e, q_pdu.tag))
cb(r_msg)
diff --git a/rpki/rootd.py b/rpki/rootd.py
index c8398ef7..818f09c7 100644
--- a/rpki/rootd.py
+++ b/rpki/rootd.py
@@ -277,8 +277,8 @@ class main(object):
except (rpki.async.ExitNow, SystemExit):
raise
except Exception, e:
- rpki.log.traceback(logger)
- return cb(400, reason = "Could not process PDU: %s" % e)
+ logger.exception("Problem decoding PDU")
+ return cb(400, reason = "Could not decode PDU: %s" % e)
def done(r_msg):
cb(200, body = cms_msg().wrap(
@@ -290,13 +290,13 @@ class main(object):
except (rpki.async.ExitNow, SystemExit):
raise
except Exception, e:
- rpki.log.traceback(logger)
try:
+ logger.exception("Exception serving up-down request %r", q_msg)
done(q_msg.serve_error(e))
except (rpki.async.ExitNow, SystemExit):
raise
except Exception, e:
- rpki.log.traceback(logger)
+ logger.exception("Exception while generating error report")
cb(500, reason = "Could not process PDU: %s" % e)
diff --git a/rpki/rpkid.py b/rpki/rpkid.py
index b619b8e2..3dc14aac 100644
--- a/rpki/rpkid.py
+++ b/rpki/rpkid.py
@@ -279,7 +279,7 @@ class main(object):
except (rpki.async.ExitNow, SystemExit):
raise
except Exception, e:
- rpki.log.traceback(logger)
+ logger.exception("Unhandled exception serving left-right request")
cb(500, reason = "Unhandled exception %s: %s" % (e.__class__.__name__, e))
up_down_url_regexp = re.compile("/up-down/([-A-Z0-9_]+)/([-A-Z0-9_]+)$", re.I)
@@ -311,7 +311,7 @@ class main(object):
logger.warning(str(e))
cb(400, reason = str(e))
except Exception, e:
- rpki.log.traceback(logger)
+ logger.exception("Unhandled exception processing up-down request")
cb(400, reason = "Could not process PDU: %s" % e)
def checkpoint(self, force = False):
@@ -662,8 +662,7 @@ class ca_obj(rpki.sql.sql_persistent):
"""
def lose(e):
- rpki.log.traceback(logger)
- logger.warning("Could not delete CA %r, skipping: %s" % (self, e))
+ logger.exception("Could not delete CA %r, skipping", self)
callback()
def done():
diff --git a/rpki/rpkid_tasks.py b/rpki/rpkid_tasks.py
index 0d5048b2..8a948dd1 100644
--- a/rpki/rpkid_tasks.py
+++ b/rpki/rpkid_tasks.py
@@ -182,9 +182,7 @@ class PollParentTask(AbstractTask):
rpki.async.iterator(r_msg.payload.classes, self.class_loop, self.class_done)
def list_failed(self, e):
- rpki.log.traceback(logger)
- logger.warning("Couldn't get resource class list from parent %r, skipping: %s (%r)" % (
- self.parent, e, e))
+ logger.exception("Couldn't get resource class list from parent %r, skipping", self.parent)
self.parent_iterator()
def class_loop(self, class_iterator, rc):
@@ -198,13 +196,11 @@ class PollParentTask(AbstractTask):
ca.check_for_updates(self.parent, rc, class_iterator, self.class_update_failed)
def class_update_failed(self, e):
- rpki.log.traceback(logger)
- logger.warning("Couldn't update class, skipping: %s" % e)
+ logger.exception("Couldn't update class, skipping")
self.class_iterator()
def class_create_failed(self, e):
- rpki.log.traceback(logger)
- logger.warning("Couldn't create class, skipping: %s" % e)
+ logger.exception("Couldn't create class, skipping")
self.class_iterator()
def class_done(self):
@@ -263,8 +259,7 @@ class UpdateChildrenTask(AbstractTask):
self.iterator()
def lose(self, e):
- rpki.log.traceback(logger)
- logger.warning("Couldn't update child %r, skipping: %s" % (self.child, e))
+ logger.exception("Couldn't update child %r, skipping", self.child)
self.iterator()
def got_resources(self, irdb_resources):
@@ -336,8 +331,7 @@ class UpdateChildrenTask(AbstractTask):
self.publisher.call_pubd(self.exit, self.publication_failed)
def publication_failed(self, e):
- rpki.log.traceback(logger)
- logger.warning("Couldn't publish for %s, skipping: %s" % (self.self_handle, e))
+ logger.exception("Couldn't publish for %s, skipping", self.self_handle)
self.gctx.checkpoint()
self.exit()
@@ -425,8 +419,7 @@ class UpdateROAsTask(AbstractTask):
except rpki.exceptions.NoCoveringCertForROA:
logger.warning("No covering certificate for %r, skipping" % roa)
except Exception, e:
- rpki.log.traceback(logger)
- logger.warning("Could not update %r, skipping: %s" % (roa, e))
+ logger.exception("Could not update %r, skipping", roa)
self.count += 1
if self.overdue:
self.publish(lambda: self.postpone(iterator))
@@ -446,8 +439,7 @@ class UpdateROAsTask(AbstractTask):
self.publisher.call_pubd(done, self.publication_failed)
def publication_failed(self, e):
- rpki.log.traceback(logger)
- logger.warning("Couldn't publish for %s, skipping: %s" % (self.self_handle, e))
+ logger.exception("Couldn't publish for %s, skipping", self.self_handle)
self.gctx.checkpoint()
self.exit()
@@ -459,15 +451,13 @@ class UpdateROAsTask(AbstractTask):
except (SystemExit, rpki.async.ExitNow):
raise
except Exception, e:
- rpki.log.traceback(logger)
- logger.warning("Could not revoke %r: %s" % (roa, e))
+ logger.exception("Could not revoke %r", roa)
self.gctx.sql.sweep()
self.gctx.checkpoint()
self.publish(self.exit)
def roa_requests_failed(self, e):
- rpki.log.traceback(logger)
- logger.warning("Could not fetch ROA requests for %s, skipping: %s" % (self.self_handle, e))
+ logger.exception("Could not fetch ROA requests for %s, skipping", self.self_handle)
self.exit()
@@ -553,19 +543,16 @@ class UpdateGhostbustersTask(AbstractTask):
except (SystemExit, rpki.async.ExitNow):
raise
except Exception, e:
- rpki.log.traceback(logger)
- logger.warning("Could not update Ghostbuster records for %s, skipping: %s" % (self.self_handle, e))
+ logger.exception("Could not update Ghostbuster records for %s, skipping", self.self_handle)
self.exit()
def publication_failed(self, e):
- rpki.log.traceback(logger)
- logger.warning("Couldn't publish Ghostbuster updates for %s, skipping: %s" % (self.self_handle, e))
+ logger.exception("Couldn't publish Ghostbuster updates for %s, skipping", self.self_handle)
self.gctx.checkpoint()
self.exit()
def ghostbuster_requests_failed(self, e):
- rpki.log.traceback(logger)
- logger.warning("Could not fetch Ghostbuster record requests for %s, skipping: %s" % (self.self_handle, e))
+ logger.exception("Could not fetch Ghostbuster record requests for %s, skipping", self.self_handle)
self.exit()
@@ -656,19 +643,16 @@ class UpdateEECertificatesTask(AbstractTask):
except (SystemExit, rpki.async.ExitNow):
raise
except Exception, e:
- rpki.log.traceback(logger)
- logger.warning("Could not update EE certificates for %s, skipping: %s" % (self.self_handle, e))
+ logger.exception("Could not update EE certificates for %s, skipping", self.self_handle)
self.exit()
def publication_failed(self, e):
- rpki.log.traceback(logger)
- logger.warning("Couldn't publish EE certificate updates for %s, skipping: %s" % (self.self_handle, e))
+ logger.exception("Couldn't publish EE certificate updates for %s, skipping", self.self_handle)
self.gctx.checkpoint()
self.exit()
def get_requests_failed(self, e):
- rpki.log.traceback(logger)
- logger.warning("Could not fetch EE certificate requests for %s, skipping: %s" % (self.self_handle, e))
+ logger.exception("Could not fetch EE certificate requests for %s, skipping", self.self_handle)
self.exit()
@@ -707,16 +691,14 @@ class RegenerateCRLsAndManifestsTask(AbstractTask):
except (SystemExit, rpki.async.ExitNow):
raise
except Exception, e:
- rpki.log.traceback(logger)
- logger.warning("Couldn't regenerate CRLs and manifests for CA %r, skipping: %s" % (ca, e))
+ logger.exception("Couldn't regenerate CRLs and manifests for CA %r, skipping", ca)
self.gctx.checkpoint()
self.gctx.sql.sweep()
publisher.call_pubd(self.exit, self.lose)
def lose(self, e):
- rpki.log.traceback(logger)
- logger.warning("Couldn't publish updated CRLs and manifests for self %r, skipping: %s" % (self.self_handle, e))
+ logger.exception("Couldn't publish updated CRLs and manifests for self %r, skipping", self.self_handle)
self.gctx.checkpoint()
self.exit()
@@ -740,7 +722,6 @@ class CheckFailedPublication(AbstractTask):
publisher.call_pubd(self.exit, self.publication_failed)
def publication_failed(self, e):
- rpki.log.traceback(logger)
- logger.warning("Couldn't publish for %s, skipping: %s" % (self.self_handle, e))
+ logger.exception("Couldn't publish for %s, skipping", self.self_handle)
self.gctx.checkpoint()
self.exit()
diff --git a/rpki/up_down.py b/rpki/up_down.py
index cc4ed196..5d4ea7e6 100644
--- a/rpki/up_down.py
+++ b/rpki/up_down.py
@@ -669,7 +669,7 @@ class message_pdu(base_elt):
callback(r_msg)
def lose(e):
- rpki.log.traceback(logger)
+ logger.exception("Unhandled exception serving child %r", child)
callback(self.serve_error(e))
try:
generated by cgit v1.2.3 (git 2.25.1) at 2025-05-10 10:43:40 +0000