Skip to content

Commit

Permalink
Move LogFormatter from options.py to log.py
Browse files Browse the repository at this point in the history
  • Loading branch information
bdarnell committed Sep 9, 2012
1 parent 7d07525 commit 1bc087c
Show file tree
Hide file tree
Showing 5 changed files with 217 additions and 188 deletions.
94 changes: 94 additions & 0 deletions tornado/log.py
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand All @@ -27,3 +36,88 @@

# 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 ")
91 changes: 3 additions & 88 deletions tornado/options.py
Original file line number Diff line number Diff line change
Expand Up @@ -56,16 +56,10 @@ def connect():
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):
Expand Down Expand Up @@ -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")
Expand Down
118 changes: 118 additions & 0 deletions tornado/test/log_test.py
Original file line number Diff line number Diff line change
@@ -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"))
Loading

0 comments on commit 1bc087c

Please sign in to comment.