From a1df2bae9293d2f1f40e05a17d7de699638e18c0 Mon Sep 17 00:00:00 2001 From: Paul Jimenez Date: Mon, 26 Oct 2015 18:50:48 -0400 Subject: [PATCH] Use standard python logging. --- aspen/__main__.py | 24 ++++++++ aspen/algorithms/website.py | 4 -- aspen/configuration/__init__.py | 13 +--- aspen/logging.py | 83 ++++++++----------------- tests/test_logging.py | 103 -------------------------------- 5 files changed, 51 insertions(+), 176 deletions(-) delete mode 100644 tests/test_logging.py diff --git a/aspen/__main__.py b/aspen/__main__.py index 82f402327..83d6d9e39 100644 --- a/aspen/__main__.py +++ b/aspen/__main__.py @@ -23,5 +23,29 @@ from . import serve, website +import logging.config + +logging_cfg = { + 'version': 1, + 'formatters': { + 'threadinfo': { + 'format': "%(asctime)s pid-%(process)d thread-%(thread)d (%(threadName)s) %(levelname)s: %(message)s" + } + }, + 'handlers': { + 'console': { + 'class': 'logging.StreamHandler', + 'formatter': 'threadinfo', + 'level': 'INFO', + 'stream': 'ext://sys.stderr' + } + }, + 'root': { + 'handlers': [ 'console' ] + } +} + +logging.config.dictConfig(logging_cfg) + if __name__ == '__main__': serve(website.Website()) diff --git a/aspen/algorithms/website.py b/aspen/algorithms/website.py index 22cbcad63..a34997f6f 100644 --- a/aspen/algorithms/website.py +++ b/aspen/algorithms/website.py @@ -180,10 +180,6 @@ def log_result_of_request(website, request=None, dispatch_result=None, response= """Log access. With our own format (not Apache's). """ - if website.logging_threshold > 0: # short-circuit - return - - # What was the URL path translated to? # ==================================== diff --git a/aspen/configuration/__init__.py b/aspen/configuration/__init__.py index b04223403..67e590cb1 100644 --- a/aspen/configuration/__init__.py +++ b/aspen/configuration/__init__.py @@ -150,6 +150,8 @@ def configure(self, **kwargs): , name )) + # log appropriately + aspen.log_dammit(os.linesep.join(msgs)) # Set some attributes. # ==================== @@ -169,17 +171,6 @@ def safe_getcwd(errorstr): raise raise ConfigurationError(errorstr) - - # LOGGING_THRESHOLD - # ----------------- - # This is initially set to -1 and not 0 so that we can tell if the user - # changed it programmatically directly before we got here. I do this in - # the testing module, that's really what this is about. - if logging.LOGGING_THRESHOLD == -1: - logging.LOGGING_THRESHOLD = self.logging_threshold - # Now that we know the user's desires, we can log appropriately. - aspen.log_dammit(os.linesep.join(msgs)) - # project root if self.project_root is None: aspen.log_dammit("project_root not configured (no template bases, " diff --git a/aspen/logging.py b/aspen/logging.py index 7f24d33de..360bf4cc2 100644 --- a/aspen/logging.py +++ b/aspen/logging.py @@ -2,22 +2,7 @@ aspen.logging +++++++++++++ -Aspen logging. It's simple. - -There are log and log_dammit functions that take arbitrary positional -arguments, stringify them, write them to stdout, and flush stdout. Each line -written is prepended with process and thread identifiers. The philosophy is -that additional abstraction layers above Aspen can handle timestamping along -with piping to files, rotation, etc. PID and thread id are best handled inside -the process, however. - -The LOGGING_THRESHOLD attribute controls the amount of information that will be -logged. The level kwarg to log must be greater than or equal to the threshold -for the message to get through. Aspen itself logs at levels zero (via log with -the default level value) and one (with the log_dammit wrapper). It's expected -that your application will have its own wrapper(s). - -Unicode objects are encoded as UTF-8. Bytestrings are passed through as-is. +Aspen logging convenience wrappers """ from __future__ import absolute_import @@ -25,51 +10,33 @@ from __future__ import print_function from __future__ import unicode_literals -from __future__ import with_statement -import os -import pprint import sys -import thread -import threading - - -LOGGING_THRESHOLD = -1 -PID = os.getpid() -LOCK = threading.Lock() - - -def stringify(o): - """Given an object, return a str, never raising ever. - """ - if isinstance(o, str): - o = o - elif isinstance(o, unicode): - o = o.encode('UTF-8', 'backslashreplace') - else: - o = pprint.pformat(o) - return o +import pprint +import logging +LOGGING_THRESHOLD = 0 def log(*messages, **kw): - level = kw.get('level', 0) - if level >= LOGGING_THRESHOLD: - # Be sure to use Python 2.5-compatible threading API. - t = threading.currentThread() - fmt = "pid-%s thread-%s (%s) %%s" % ( PID - , thread.get_ident() - , t.getName() - ) - for message in messages: - message = stringify(message) - for line in message.splitlines(): - with LOCK: - # Log lines can get interleaved, but that's okay, because - # we prepend lines with thread identifiers that can be used - # to reassemble log messages per-thread. - print(fmt % line.decode('utf8')) - sys.stdout.flush() + """ + Make logging more convenient - use magic to get the __name__ of the calling module/function + and log as it. + 'level' if present as a kwarg, is the level to log at. + 'upframes' if present as a kwarg, is how many frames up to look for the name. -def log_dammit(*messages): - log(*messages, **{'level': 1}) - #log(*messages, level=1) <-- SyntaxError in Python 2.5 + other kwargs are passed through to Logger.log() + """ + level = kw.get('level', logging.WARNING) + if 'level' in kw: del kw['level'] + upframes = kw.get('upframes', 1) + if 'upframes' in kw: del kw['upframes'] + callerName = sys._getframe(upframes).f_globals.get('__name__', '') + logging.getLogger(callerName).log(level, *messages, **kw) + +def log_dammit(*messages, **kw): + """ + like log(), but critical instead of warning + """ + kw['level'] = kw.get('level', logging.CRITICAL) + kw['upframes'] = kw.get('upframes', 2) + log(*messages, **kw) diff --git a/tests/test_logging.py b/tests/test_logging.py deleted file mode 100644 index 677912558..000000000 --- a/tests/test_logging.py +++ /dev/null @@ -1,103 +0,0 @@ -from __future__ import absolute_import -from __future__ import division -from __future__ import print_function -from __future__ import unicode_literals - -import re -import os -import sys -from StringIO import StringIO - -import aspen.logging -from algorithm import Algorithm -from aspen import Response -from aspen.logging import log, log_dammit -from aspen.algorithms.website import log_result_of_request - - -pat = re.compile("pid-\d* thread--?\d* \(MainThread\) (.*)") -def capture(*a, **kw): - """This is a fixture function to capture log output. - - Positional and keyword arguments are passed through to a logging function - with these exceptions, which are pulled out of kw before that is passed - through to the logging function: - - func the logging function to use, defaults to log - threshold where to set the logging threshold; it will be reset to its - previous value after the output of func is captured - - """ - func = kw.pop('func') if 'func' in kw else log - try: - __threshold__ = aspen.logging.LOGGING_THRESHOLD - if 'threshold' in kw: - aspen.logging.LOGGING_THRESHOLD = kw.pop('threshold') - sys.stdout = StringIO() - func(*a, **kw) - output = sys.stdout.getvalue() - finally: - aspen.logging.LOGGING_THRESHOLD = __threshold__ - sys.stdout = sys.__stdout__ - return pat.findall(output) - - -def test_log_logs_something(): - actual = capture("oh heck", level=4) - assert actual == ["oh heck"] - -def test_log_logs_several_somethings(): - actual = capture("oh\nheck", u"what?", {}, [], None, level=4) - assert actual == ["oh", "heck", "what?", "{}", "[]", "None"] - -def test_log_dammit_works(): - actual = capture("yes\nrly", {}, [], None, threshold=1, func=log_dammit) - assert actual == ["yes", "rly", "{}", "[]", "None"] - -def test_logging_unicode_works(): - actual = capture("oh \u2614 heck", level=4) - assert actual == ["oh \u2614 heck"] - - - -# lror - log_result_of_request - -def lror(**kw): - """Wrap log_result_of_request in an Algorithm to better simulate reality. - """ - Algorithm(log_result_of_request).run(**kw) - -def test_lror_logs_result_of_request(harness): - state = harness.simple(want='state', return_after='dispatch_request_to_filesystem') - request = state['request'] - dispatch_result = state['dispatch_result'] - response = Response(200, "Greetings, program!") - actual = capture( func=lror - , website=harness.client.website - , request=request - , dispatch_result=dispatch_result - , response=response - ) - assert actual == [ - '200 OK / .%sindex.html.spt' % os.sep - ] - -def test_lror_logs_result_of_request_and_dispatch_result_are_none(harness): - response = Response(500, "Failure, program!") - actual = capture(func=lror, website=harness.client.website, response=response) - assert actual == [ - '500 Internal Server Error (no request available)' - ] - -def test_lror_logs_result_of_request_when_response_is_none(harness): - state = harness.simple(want='state', return_after='dispatch_request_to_filesystem') - request = state['request'] - dispatch_result = state['dispatch_result'] - actual = capture( func=lror - , website=harness.client.website - , request=request - , dispatch_result=dispatch_result - ) - assert actual == [ - '(no response available) / .%sindex.html.spt' % os.sep - ]