From e6047c9f737275d898d88737719dd09a6ee4f25c Mon Sep 17 00:00:00 2001 From: Rob Austein Date: Thu, 29 May 2014 19:18:40 +0000 Subject: Provide our own logging Formatter class rather than straining to subclass the stock one. Replace all uses of rpki.log.traceback() with logging package .exception() calls. Use LoggingAdapter for all the whacky per-stream logging code in rpki.http. Fix default logging priority for non-daemon programs like rpkic. svn path=/trunk/; revision=5843 --- ca/tests/smoketest.py | 14 ++---- ca/tests/testpoke.py | 1 - ca/tests/yamlconf.py | 3 +- ca/tests/yamltest.py | 3 +- rpki/async.py | 3 +- rpki/http.py | 137 +++++++++++++++++++------------------------------- rpki/irdbd.py | 4 +- rpki/left_right.py | 4 +- rpki/log.py | 96 +++++++++++++++++------------------ rpki/old_irdbd.py | 10 ++-- rpki/pubd.py | 4 +- rpki/publication.py | 2 +- rpki/rootd.py | 8 +-- rpki/rpkid.py | 7 ++- rpki/rpkid_tasks.py | 55 +++++++------------- rpki/up_down.py | 2 +- 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 - # , 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: -- cgit v1.2.3