From: Ben Darnell Date: Sun, 9 Sep 2012 04:35:51 +0000 (-0700) Subject: Move LogFormatter from options.py to log.py X-Git-Tag: v3.0.0~272^2~23 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=1bc087c024b0949cafa9b81e026a603dd1e806d1;p=thirdparty%2Ftornado.git Move LogFormatter from options.py to log.py --- diff --git a/tornado/log.py b/tornado/log.py index 96b9998db..c76d404db 100644 --- a/tornado/log.py +++ b/tornado/log.py @@ -16,6 +16,15 @@ from __future__ import absolute_import, division, with_statement import logging +import sys +import time + +from tornado.escape import _unicode + +try: + import curses +except ImportError: + curses = None # Per-request logging for Tornado's HTTP servers (and potentially other servers # in the future) @@ -27,3 +36,88 @@ app_log = logging.getLogger("tornado.application") # General logging, i.e. everything else gen_log = logging.getLogger("tornado.general") + +def _stderr_supports_color(): + color = False + if curses and sys.stderr.isatty(): + try: + curses.setupterm() + if curses.tigetnum("colors") > 0: + color = True + except Exception: + pass + return color + + +class LogFormatter(logging.Formatter): + def __init__(self, color=None, *args, **kwargs): + logging.Formatter.__init__(self, *args, **kwargs) + if color is None: + color = _stderr_supports_color() + self._color = color + if color: + # The curses module has some str/bytes confusion in + # python3. Until version 3.2.3, most methods return + # bytes, but only accept strings. In addition, we want to + # output these strings with the logging module, which + # works with unicode strings. The explicit calls to + # unicode() below are harmless in python2 but will do the + # right conversion in python 3. + fg_color = (curses.tigetstr("setaf") or + curses.tigetstr("setf") or "") + if (3, 0) < sys.version_info < (3, 2, 3): + fg_color = unicode(fg_color, "ascii") + self._colors = { + logging.DEBUG: unicode(curses.tparm(fg_color, 4), # Blue + "ascii"), + logging.INFO: unicode(curses.tparm(fg_color, 2), # Green + "ascii"), + logging.WARNING: unicode(curses.tparm(fg_color, 3), # Yellow + "ascii"), + logging.ERROR: unicode(curses.tparm(fg_color, 1), # Red + "ascii"), + } + self._normal = unicode(curses.tigetstr("sgr0"), "ascii") + + def format(self, record): + try: + record.message = record.getMessage() + except Exception, e: + record.message = "Bad message (%r): %r" % (e, record.__dict__) + assert isinstance(record.message, basestring) # guaranteed by logging + record.asctime = time.strftime( + "%y%m%d %H:%M:%S", self.converter(record.created)) + prefix = '[%(levelname)1.1s %(asctime)s %(module)s:%(lineno)d]' % \ + record.__dict__ + if self._color: + prefix = (self._colors.get(record.levelno, self._normal) + + prefix + self._normal) + + # Encoding notes: The logging module prefers to work with character + # strings, but only enforces that log messages are instances of + # basestring. In python 2, non-ascii bytestrings will make + # their way through the logging framework until they blow up with + # an unhelpful decoding error (with this formatter it happens + # when we attach the prefix, but there are other opportunities for + # exceptions further along in the framework). + # + # If a byte string makes it this far, convert it to unicode to + # ensure it will make it out to the logs. Use repr() as a fallback + # to ensure that all byte strings can be converted successfully, + # but don't do it by default so we don't add extra quotes to ascii + # bytestrings. This is a bit of a hacky place to do this, but + # it's worth it since the encoding errors that would otherwise + # result are so useless (and tornado is fond of using utf8-encoded + # byte strings whereever possible). + try: + message = _unicode(record.message) + except UnicodeDecodeError: + message = repr(record.message) + + formatted = prefix + " " + message + if record.exc_info: + if not record.exc_text: + record.exc_text = self.formatException(record.exc_info) + if record.exc_text: + formatted = formatted.rstrip() + "\n" + record.exc_text + return formatted.replace("\n", "\n ") diff --git a/tornado/options.py b/tornado/options.py index a3d74d68d..1f15050e1 100644 --- a/tornado/options.py +++ b/tornado/options.py @@ -56,16 +56,10 @@ import logging.handlers import re import sys import os -import time import textwrap from tornado.escape import _unicode - -# For pretty log messages, if available -try: - import curses -except ImportError: - curses = None +from tornado.log import LogFormatter class Error(Exception): @@ -369,96 +363,17 @@ def enable_pretty_logging(options=options): filename=options.log_file_prefix, maxBytes=options.log_file_max_size, backupCount=options.log_file_num_backups) - channel.setFormatter(_LogFormatter(color=False)) + channel.setFormatter(LogFormatter(color=False)) root_logger.addHandler(channel) if (options.log_to_stderr or (options.log_to_stderr is None and not root_logger.handlers)): # Set up color if we are in a tty and curses is installed - color = False - if curses and sys.stderr.isatty(): - try: - curses.setupterm() - if curses.tigetnum("colors") > 0: - color = True - except Exception: - pass channel = logging.StreamHandler() - channel.setFormatter(_LogFormatter(color=color)) + channel.setFormatter(LogFormatter()) root_logger.addHandler(channel) -class _LogFormatter(logging.Formatter): - def __init__(self, color, *args, **kwargs): - logging.Formatter.__init__(self, *args, **kwargs) - self._color = color - if color: - # The curses module has some str/bytes confusion in - # python3. Until version 3.2.3, most methods return - # bytes, but only accept strings. In addition, we want to - # output these strings with the logging module, which - # works with unicode strings. The explicit calls to - # unicode() below are harmless in python2 but will do the - # right conversion in python 3. - fg_color = (curses.tigetstr("setaf") or - curses.tigetstr("setf") or "") - if (3, 0) < sys.version_info < (3, 2, 3): - fg_color = unicode(fg_color, "ascii") - self._colors = { - logging.DEBUG: unicode(curses.tparm(fg_color, 4), # Blue - "ascii"), - logging.INFO: unicode(curses.tparm(fg_color, 2), # Green - "ascii"), - logging.WARNING: unicode(curses.tparm(fg_color, 3), # Yellow - "ascii"), - logging.ERROR: unicode(curses.tparm(fg_color, 1), # Red - "ascii"), - } - self._normal = unicode(curses.tigetstr("sgr0"), "ascii") - - def format(self, record): - try: - record.message = record.getMessage() - except Exception, e: - record.message = "Bad message (%r): %r" % (e, record.__dict__) - assert isinstance(record.message, basestring) # guaranteed by logging - record.asctime = time.strftime( - "%y%m%d %H:%M:%S", self.converter(record.created)) - prefix = '[%(levelname)1.1s %(asctime)s %(module)s:%(lineno)d]' % \ - record.__dict__ - if self._color: - prefix = (self._colors.get(record.levelno, self._normal) + - prefix + self._normal) - - # Encoding notes: The logging module prefers to work with character - # strings, but only enforces that log messages are instances of - # basestring. In python 2, non-ascii bytestrings will make - # their way through the logging framework until they blow up with - # an unhelpful decoding error (with this formatter it happens - # when we attach the prefix, but there are other opportunities for - # exceptions further along in the framework). - # - # If a byte string makes it this far, convert it to unicode to - # ensure it will make it out to the logs. Use repr() as a fallback - # to ensure that all byte strings can be converted successfully, - # but don't do it by default so we don't add extra quotes to ascii - # bytestrings. This is a bit of a hacky place to do this, but - # it's worth it since the encoding errors that would otherwise - # result are so useless (and tornado is fond of using utf8-encoded - # byte strings whereever possible). - try: - message = _unicode(record.message) - except UnicodeDecodeError: - message = repr(record.message) - - formatted = prefix + " " + message - if record.exc_info: - if not record.exc_text: - record.exc_text = self.formatException(record.exc_info) - if record.exc_text: - formatted = formatted.rstrip() + "\n" + record.exc_text - return formatted.replace("\n", "\n ") - # Default options define("help", type=bool, help="show this help information") diff --git a/tornado/test/log_test.py b/tornado/test/log_test.py new file mode 100644 index 000000000..a7e5992f8 --- /dev/null +++ b/tornado/test/log_test.py @@ -0,0 +1,118 @@ +#!/usr/bin/env python +# +# Copyright 2012 Facebook +# +# Licensed under the Apache License, Version 2.0 (the "License"); you may +# not use this file except in compliance with the License. You may obtain +# a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, WITHOUT +# WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the +# License for the specific language governing permissions and limitations +# under the License. +from __future__ import absolute_import, division, with_statement + +import contextlib +import logging +import os +import re +import tempfile +import warnings + +from tornado.escape import utf8 +from tornado.log import LogFormatter +from tornado.test.util import unittest +from tornado.util import b, bytes_type + +@contextlib.contextmanager +def ignore_bytes_warning(): + if not hasattr(warnings, 'catch_warnings'): + # python 2.5 doesn't have catch_warnings, but it doesn't have + # BytesWarning either so there's nothing to catch. + yield + return + with warnings.catch_warnings(): + warnings.simplefilter('ignore', category=BytesWarning) + yield + + +class LogFormatterTest(unittest.TestCase): + LINE_RE = re.compile(b("\x01\\[E [0-9]{6} [0-9]{2}:[0-9]{2}:[0-9]{2} log_test:[0-9]+\\]\x02 (.*)")) + + def setUp(self): + self.formatter = LogFormatter(color=False) + # Fake color support. We can't guarantee anything about the $TERM + # variable when the tests are run, so just patch in some values + # for testing. (testing with color off fails to expose some potential + # encoding issues from the control characters) + self.formatter._colors = { + logging.ERROR: u"\u0001", + } + self.formatter._normal = u"\u0002" + self.formatter._color = True + # construct a Logger directly to bypass getLogger's caching + self.logger = logging.Logger('LogFormatterTest') + self.logger.propagate = False + self.tempdir = tempfile.mkdtemp() + self.filename = os.path.join(self.tempdir, 'log.out') + self.handler = self.make_handler(self.filename) + self.handler.setFormatter(self.formatter) + self.logger.addHandler(self.handler) + + def tearDown(self): + self.handler.close() + os.unlink(self.filename) + os.rmdir(self.tempdir) + + def make_handler(self, filename): + # Base case: default setup without explicit encoding. + # In python 2, supports arbitrary byte strings and unicode objects + # that contain only ascii. In python 3, supports ascii-only unicode + # strings (but byte strings will be repr'd automatically). + return logging.FileHandler(filename) + + def get_output(self): + with open(self.filename, "rb") as f: + line = f.read().strip() + m = LogFormatterTest.LINE_RE.match(line) + if m: + return m.group(1) + else: + raise Exception("output didn't match regex: %r" % line) + + def test_basic_logging(self): + self.logger.error("foo") + self.assertEqual(self.get_output(), b("foo")) + + def test_bytes_logging(self): + with ignore_bytes_warning(): + # This will be "\xe9" on python 2 or "b'\xe9'" on python 3 + self.logger.error(b("\xe9")) + self.assertEqual(self.get_output(), utf8(repr(b("\xe9")))) + + def test_utf8_logging(self): + self.logger.error(u"\u00e9".encode("utf8")) + if issubclass(bytes_type, basestring): + # on python 2, utf8 byte strings (and by extension ascii byte + # strings) are passed through as-is. + self.assertEqual(self.get_output(), utf8(u"\u00e9")) + else: + # on python 3, byte strings always get repr'd even if + # they're ascii-only, so this degenerates into another + # copy of test_bytes_logging. + self.assertEqual(self.get_output(), utf8(repr(utf8(u"\u00e9")))) + + +class UnicodeLogFormatterTest(LogFormatterTest): + def make_handler(self, filename): + # Adding an explicit encoding configuration allows non-ascii unicode + # strings in both python 2 and 3, without changing the behavior + # for byte strings. + return logging.FileHandler(filename, encoding="utf8") + + def test_unicode_logging(self): + self.logger.error(u"\u00e9") + self.assertEqual(self.get_output(), utf8(u"\u00e9")) diff --git a/tornado/test/options_test.py b/tornado/test/options_test.py index c815935c9..b235416cf 100644 --- a/tornado/test/options_test.py +++ b/tornado/test/options_test.py @@ -1,27 +1,7 @@ from __future__ import absolute_import, division, with_statement -import contextlib -import logging -import os -import re -import tempfile -import warnings -from tornado.escape import utf8 -from tornado.options import _Options, _LogFormatter +from tornado.options import _Options from tornado.test.util import unittest -from tornado.util import b, bytes_type - - -@contextlib.contextmanager -def ignore_bytes_warning(): - if not hasattr(warnings, 'catch_warnings'): - # python 2.5 doesn't have catch_warnings, but it doesn't have - # BytesWarning either so there's nothing to catch. - yield - return - with warnings.catch_warnings(): - warnings.simplefilter('ignore', category=BytesWarning) - yield class OptionsTest(unittest.TestCase): @@ -37,82 +17,3 @@ class OptionsTest(unittest.TestCase): def test_parse_command_line(self): self.options.parse_command_line(["main.py", "--port=443"]) self.assertEqual(self.options.port, 443) - - -class LogFormatterTest(unittest.TestCase): - LINE_RE = re.compile(b("\x01\\[E [0-9]{6} [0-9]{2}:[0-9]{2}:[0-9]{2} options_test:[0-9]+\\]\x02 (.*)")) - - def setUp(self): - self.formatter = _LogFormatter(color=False) - # Fake color support. We can't guarantee anything about the $TERM - # variable when the tests are run, so just patch in some values - # for testing. (testing with color off fails to expose some potential - # encoding issues from the control characters) - self.formatter._colors = { - logging.ERROR: u"\u0001", - } - self.formatter._normal = u"\u0002" - self.formatter._color = True - # construct a Logger directly to bypass getLogger's caching - self.logger = logging.Logger('LogFormatterTest') - self.logger.propagate = False - self.tempdir = tempfile.mkdtemp() - self.filename = os.path.join(self.tempdir, 'log.out') - self.handler = self.make_handler(self.filename) - self.handler.setFormatter(self.formatter) - self.logger.addHandler(self.handler) - - def tearDown(self): - self.handler.close() - os.unlink(self.filename) - os.rmdir(self.tempdir) - - def make_handler(self, filename): - # Base case: default setup without explicit encoding. - # In python 2, supports arbitrary byte strings and unicode objects - # that contain only ascii. In python 3, supports ascii-only unicode - # strings (but byte strings will be repr'd automatically). - return logging.FileHandler(filename) - - def get_output(self): - with open(self.filename, "rb") as f: - line = f.read().strip() - m = LogFormatterTest.LINE_RE.match(line) - if m: - return m.group(1) - else: - raise Exception("output didn't match regex: %r" % line) - - def test_basic_logging(self): - self.logger.error("foo") - self.assertEqual(self.get_output(), b("foo")) - - def test_bytes_logging(self): - with ignore_bytes_warning(): - # This will be "\xe9" on python 2 or "b'\xe9'" on python 3 - self.logger.error(b("\xe9")) - self.assertEqual(self.get_output(), utf8(repr(b("\xe9")))) - - def test_utf8_logging(self): - self.logger.error(u"\u00e9".encode("utf8")) - if issubclass(bytes_type, basestring): - # on python 2, utf8 byte strings (and by extension ascii byte - # strings) are passed through as-is. - self.assertEqual(self.get_output(), utf8(u"\u00e9")) - else: - # on python 3, byte strings always get repr'd even if - # they're ascii-only, so this degenerates into another - # copy of test_bytes_logging. - self.assertEqual(self.get_output(), utf8(repr(utf8(u"\u00e9")))) - - -class UnicodeLogFormatterTest(LogFormatterTest): - def make_handler(self, filename): - # Adding an explicit encoding configuration allows non-ascii unicode - # strings in both python 2 and 3, without changing the behavior - # for byte strings. - return logging.FileHandler(filename, encoding="utf8") - - def test_unicode_logging(self): - self.logger.error(u"\u00e9") - self.assertEqual(self.get_output(), utf8(u"\u00e9")) diff --git a/tornado/test/runtests.py b/tornado/test/runtests.py index cba692f21..13c03ce85 100644 --- a/tornado/test/runtests.py +++ b/tornado/test/runtests.py @@ -20,6 +20,7 @@ TEST_MODULES = [ 'tornado.test.ioloop_test', 'tornado.test.iostream_test', 'tornado.test.locale_test', + 'tornado.test.log_test', 'tornado.test.options_test', 'tornado.test.process_test', 'tornado.test.simple_httpclient_test',