Skip to content

Commit

Permalink
Send all logging to the root logger instead of per-module loggers.
Browse files Browse the repository at this point in the history
This undoes the effect of
http://github.com/facebook/tornado/commit/e391fd289ed085671344504cc5b1fa84f5a3c774

Per-module loggers are problematic because only the top-level convenience
logging.{error,warning,...} functions configure logging on-demand, so
an app that only uses per-module loggers will produce no output except
"no handlers found for logger X".  Since tornado.ioloop swallows and logs
all exceptions, this makes it too hard to tell what's going on for apps
that do not configure logging explicitly.

Instead of setting log levels on individual module's loggers,
logging.Handler.addFilter can be used with a filter that examines
the module attribute of the log record.
  • Loading branch information
Ben Darnell committed Apr 20, 2010
1 parent 40ac8d3 commit ca8002f
Show file tree
Hide file tree
Showing 12 changed files with 62 additions and 86 deletions.
20 changes: 9 additions & 11 deletions tornado/auth.py
Expand Up @@ -58,8 +58,6 @@ def _on_auth(self, user):
import urlparse
import uuid

_log = logging.getLogger("tornado.auth")

class OpenIdMixin(object):
"""Abstract implementation of OpenID and Attribute Exchange.
Expand Down Expand Up @@ -146,7 +144,7 @@ def _openid_args(self, callback_uri, ax_attrs=[], oauth_scope=None):

def _on_authentication_verified(self, callback, response):
if response.error or u"is_valid:true" not in response.body:
_log.warning("Invalid OpenID response: %s", response.error or
logging.warning("Invalid OpenID response: %s", response.error or
response.body)
callback(None)
return
Expand Down Expand Up @@ -233,12 +231,12 @@ def get_authenticated_user(self, callback):
request_key = self.get_argument("oauth_token")
request_cookie = self.get_cookie("_oauth_request_token")
if not request_cookie:
_log.warning("Missing OAuth request token cookie")
logging.warning("Missing OAuth request token cookie")
callback(None)
return
cookie_key, cookie_secret = request_cookie.split("|")
if cookie_key != request_key:
_log.warning("Request token does not match cookie")
logging.warning("Request token does not match cookie")
callback(None)
return
token = dict(key=cookie_key, secret=cookie_secret)
Expand Down Expand Up @@ -290,7 +288,7 @@ def _oauth_access_token_url(self, request_token):

def _on_access_token(self, callback, response):
if response.error:
_log.warning("Could not fetch access token")
logging.warning("Could not fetch access token")
callback(None)
return
access_token = _oauth_parse_response(response.body)
Expand Down Expand Up @@ -442,7 +440,7 @@ def _on_post(self, new_entry):

def _on_twitter_request(self, callback, response):
if response.error:
_log.warning("Error response %s fetching %s", response.error,
logging.warning("Error response %s fetching %s", response.error,
response.request.url)
callback(None)
return
Expand Down Expand Up @@ -562,7 +560,7 @@ def _on_post(self, new_entry):

def _on_friendfeed_request(self, callback, response):
if response.error:
_log.warning("Error response %s fetching %s", response.error,
logging.warning("Error response %s fetching %s", response.error,
response.request.url)
callback(None)
return
Expand Down Expand Up @@ -820,17 +818,17 @@ def _on_get_user_info(self, callback, session, users):

def _parse_response(self, callback, response):
if response.error:
_log.warning("HTTP error from Facebook: %s", response.error)
logging.warning("HTTP error from Facebook: %s", response.error)
callback(None)
return
try:
json = escape.json_decode(response.body)
except:
_log.warning("Invalid JSON from Facebook: %r", response.body)
logging.warning("Invalid JSON from Facebook: %r", response.body)
callback(None)
return
if isinstance(json, dict) and json.get("error_code"):
_log.warning("Facebook error: %d: %r", json["error_code"],
logging.warning("Facebook error: %d: %r", json["error_code"],
json.get("error_msg"))
callback(None)
return
Expand Down
4 changes: 1 addition & 3 deletions tornado/autoreload.py
Expand Up @@ -29,8 +29,6 @@
import sys
import types

_log = logging.getLogger('tornado.autoreload')

def start(io_loop=None, check_time=500):
"""Restarts the process automatically when a module is modified.
Expand Down Expand Up @@ -69,7 +67,7 @@ def _reload_on_update(io_loop, modify_times):
modify_times[path] = modified
continue
if modify_times[path] != modified:
_log.info("%s modified; restarting server", path)
logging.info("%s modified; restarting server", path)
_reload_attempted = True
for fd in io_loop._handlers.keys():
try:
Expand Down
6 changes: 2 additions & 4 deletions tornado/database.py
Expand Up @@ -24,8 +24,6 @@
import itertools
import logging

_log = logging.getLogger('tornado.database')

class Connection(object):
"""A lightweight wrapper around MySQLdb DB-API connections.
Expand Down Expand Up @@ -72,7 +70,7 @@ def __init__(self, host, database, user=None, password=None):
try:
self.reconnect()
except:
_log.error("Cannot connect to MySQL on %s", self.host,
logging.error("Cannot connect to MySQL on %s", self.host,
exc_info=True)

def __del__(self):
Expand Down Expand Up @@ -151,7 +149,7 @@ def _execute(self, cursor, query, parameters):
try:
return cursor.execute(query, parameters)
except OperationalError:
_log.error("Error connecting to MySQL on %s", self.host)
logging.error("Error connecting to MySQL on %s", self.host)
self.close()
raise

Expand Down
16 changes: 7 additions & 9 deletions tornado/httpclient.py
Expand Up @@ -29,8 +29,6 @@
import time
import weakref

_log = logging.getLogger('tornado.httpclient')

class HTTPClient(object):
"""A blocking HTTP client backed with pycurl.
Expand Down Expand Up @@ -348,7 +346,7 @@ def __init__(self, errno, message):

def _curl_create(max_simultaneous_connections=None):
curl = pycurl.Curl()
if _log.isEnabledFor(logging.DEBUG):
if logging.getLogger().isEnabledFor(logging.DEBUG):
curl.setopt(pycurl.VERBOSE, 1)
curl.setopt(pycurl.DEBUGFUNCTION, _curl_debug)
curl.setopt(pycurl.MAXCONNECTS, max_simultaneous_connections or 5)
Expand Down Expand Up @@ -423,11 +421,11 @@ def ioctl(cmd):
userpwd = "%s:%s" % (request.auth_username, request.auth_password)
curl.setopt(pycurl.HTTPAUTH, pycurl.HTTPAUTH_BASIC)
curl.setopt(pycurl.USERPWD, userpwd)
_log.info("%s %s (username: %r)", request.method, request.url,
logging.info("%s %s (username: %r)", request.method, request.url,
request.auth_username)
else:
curl.unsetopt(pycurl.USERPWD)
_log.info("%s %s", request.method, request.url)
logging.info("%s %s", request.method, request.url)
if request.prepare_curl_callback is not None:
request.prepare_curl_callback(curl)

Expand All @@ -440,7 +438,7 @@ def _curl_header_callback(headers, header_line):
return
parts = header_line.split(":", 1)
if len(parts) != 2:
_log.warning("Invalid HTTP response header line %r", header_line)
logging.warning("Invalid HTTP response header line %r", header_line)
return
name = parts[0].strip()
value = parts[1].strip()
Expand All @@ -453,12 +451,12 @@ def _curl_header_callback(headers, header_line):
def _curl_debug(debug_type, debug_msg):
debug_types = ('I', '<', '>', '<', '>')
if debug_type == 0:
_log.debug('%s', debug_msg.strip())
logging.debug('%s', debug_msg.strip())
elif debug_type in (1, 2):
for line in debug_msg.splitlines():
_log.debug('%s %s', debug_types[debug_type], line)
logging.debug('%s %s', debug_types[debug_type], line)
elif debug_type == 4:
_log.debug('%s %r', debug_types[debug_type], debug_msg)
logging.debug('%s %r', debug_types[debug_type], debug_msg)


def _utf8(value):
Expand Down
16 changes: 7 additions & 9 deletions tornado/httpserver.py
Expand Up @@ -40,8 +40,6 @@
except ImportError:
ssl = None

_log = logging.getLogger('tornado.httpserver')

class HTTPServer(object):
"""A non-blocking, single-threaded HTTP server.
Expand Down Expand Up @@ -172,16 +170,16 @@ def start(self, num_processes=None):
try:
num_processes = os.sysconf("SC_NPROCESSORS_CONF")
except ValueError:
_log.error("Could not get num processors from sysconf; "
logging.error("Could not get num processors from sysconf; "
"running with one process")
num_processes = 1
if num_processes > 1 and ioloop.IOLoop.initialized():
_log.error("Cannot run in multiple processes: IOLoop instance "
logging.error("Cannot run in multiple processes: IOLoop instance "
"has already been initialized. You cannot call "
"IOLoop.instance() before calling start()")
num_processes = 1
if num_processes > 1:
_log.info("Pre-forking %d server processes", num_processes)
logging.info("Pre-forking %d server processes", num_processes)
for i in range(num_processes):
if os.fork() == 0:
self.io_loop = ioloop.IOLoop.instance()
Expand Down Expand Up @@ -218,7 +216,7 @@ def _handle_events(self, fd, events):
HTTPConnection(stream, address, self.request_callback,
self.no_keep_alive, self.xheaders)
except:
_log.error("Error in connection callback", exc_info=True)
logging.error("Error in connection callback", exc_info=True)


class HTTPConnection(object):
Expand Down Expand Up @@ -321,21 +319,21 @@ def _parse_mime_body(self, boundary, data):
if not part: continue
eoh = part.find("\r\n\r\n")
if eoh == -1:
_log.warning("multipart/form-data missing headers")
logging.warning("multipart/form-data missing headers")
continue
headers = HTTPHeaders.parse(part[:eoh])
name_header = headers.get("Content-Disposition", "")
if not name_header.startswith("form-data;") or \
not part.endswith("\r\n"):
_log.warning("Invalid multipart/form-data")
logging.warning("Invalid multipart/form-data")
continue
value = part[eoh + 4:-2]
name_values = {}
for name_part in name_header[10:].split(";"):
name, name_value = name_part.strip().split("=", 1)
name_values[name] = name_value.strip('"').decode("utf-8")
if not name_values.get("name"):
_log.warning("multipart/form-data value missing name")
logging.warning("multipart/form-data value missing name")
continue
name = name_values["name"]
if name_values.get("filename"):
Expand Down
16 changes: 7 additions & 9 deletions tornado/ioloop.py
Expand Up @@ -32,8 +32,6 @@
else:
raise

_log = logging.getLogger("tornado.ioloop")

class IOLoop(object):
"""A level-triggered I/O loop.
Expand Down Expand Up @@ -154,7 +152,7 @@ def remove_handler(self, fd):
try:
self._impl.unregister(fd)
except (OSError, IOError):
_log.debug("Error deleting fd from IOLoop", exc_info=True)
logging.debug("Error deleting fd from IOLoop", exc_info=True)

def start(self):
"""Starts the I/O loop.
Expand Down Expand Up @@ -198,7 +196,7 @@ def start(self):
event_pairs = self._impl.poll(poll_timeout)
except Exception, e:
if hasattr(e, 'errno') and e.errno == errno.EINTR:
_log.warning("Interrupted system call", exc_info=1)
logging.warning("Interrupted system call", exc_info=1)
continue
else:
raise
Expand All @@ -219,10 +217,10 @@ def start(self):
# Happens when the client closes the connection
pass
else:
_log.error("Exception in I/O handler for fd %d",
logging.error("Exception in I/O handler for fd %d",
fd, exc_info=True)
except:
_log.error("Exception in I/O handler for fd %d",
logging.error("Exception in I/O handler for fd %d",
fd, exc_info=True)
# reset the stopped flag so another start/stop pair can be issued
self._stopped = False
Expand Down Expand Up @@ -290,7 +288,7 @@ def handle_callback_exception(self, callback):
The exception itself is not passed explicitly, but is available
in sys.exc_info.
"""
_log.error("Exception in callback %r", callback, exc_info=True)
logging.error("Exception in callback %r", callback, exc_info=True)

def _read_waker(self, fd, events):
try:
Expand Down Expand Up @@ -348,7 +346,7 @@ def _run(self):
except (KeyboardInterrupt, SystemExit):
raise
except:
_log.error("Error in periodic callback", exc_info=True)
logging.error("Error in periodic callback", exc_info=True)
self.start()


Expand Down Expand Up @@ -479,5 +477,5 @@ def poll(self, timeout):
# All other systems
import sys
if "linux" in sys.platform:
_log.warning("epoll module not found; using select()")
logging.warning("epoll module not found; using select()")
_poll = _Select
10 changes: 4 additions & 6 deletions tornado/iostream.py
Expand Up @@ -21,8 +21,6 @@
import logging
import socket

_log = logging.getLogger('tornado.iostream')

class IOStream(object):
"""A utility class to write to and read from a non-blocking socket.
Expand Down Expand Up @@ -139,7 +137,7 @@ def closed(self):

def _handle_events(self, fd, events):
if not self.socket:
_log.warning("Got events for closed stream %d", fd)
logging.warning("Got events for closed stream %d", fd)
return
if events & self.io_loop.READ:
self._handle_read()
Expand Down Expand Up @@ -168,7 +166,7 @@ def _handle_read(self):
if e[0] in (errno.EWOULDBLOCK, errno.EAGAIN):
return
else:
_log.warning("Read error on %d: %s",
logging.warning("Read error on %d: %s",
self.socket.fileno(), e)
self.close()
return
Expand All @@ -177,7 +175,7 @@ def _handle_read(self):
return
self._read_buffer += chunk
if len(self._read_buffer) >= self.max_buffer_size:
_log.error("Reached maximum read buffer size")
logging.error("Reached maximum read buffer size")
self.close()
return
if self._read_bytes:
Expand Down Expand Up @@ -205,7 +203,7 @@ def _handle_write(self):
if e[0] in (errno.EWOULDBLOCK, errno.EAGAIN):
break
else:
_log.warning("Write error on %d: %s",
logging.warning("Write error on %d: %s",
self.socket.fileno(), e)
self.close()
return
Expand Down
10 changes: 4 additions & 6 deletions tornado/locale.py
Expand Up @@ -51,8 +51,6 @@
_supported_locales = frozenset([_default_locale])
_use_gettext = False

_log = logging.getLogger('tornado.locale')

def get(*locale_codes):
"""Returns the closest match for the given locale codes.
Expand Down Expand Up @@ -112,7 +110,7 @@ def load_translations(directory):
if not path.endswith(".csv"): continue
locale, extension = path.split(".")
if locale not in LOCALE_NAMES:
_log.error("Unrecognized locale %r (path: %s)", locale,
logging.error("Unrecognized locale %r (path: %s)", locale,
os.path.join(directory, path))
continue
f = open(os.path.join(directory, path), "r")
Expand All @@ -126,13 +124,13 @@ def load_translations(directory):
else:
plural = "unknown"
if plural not in ("plural", "singular", "unknown"):
_log.error("Unrecognized plural indicator %r in %s line %d",
logging.error("Unrecognized plural indicator %r in %s line %d",
plural, path, i + 1)
continue
_translations[locale].setdefault(plural, {})[english] = translation
f.close()
_supported_locales = frozenset(_translations.keys() + [_default_locale])
_log.info("Supported locales: %s", sorted(_supported_locales))
logging.info("Supported locales: %s", sorted(_supported_locales))

def load_gettext_translations(directory, domain):
"""Loads translations from gettext's locale tree
Expand Down Expand Up @@ -168,7 +166,7 @@ def load_gettext_translations(directory, domain):
continue
_supported_locales = frozenset(_translations.keys() + [_default_locale])
_use_gettext = True
_log.info("Supported locales: %s", sorted(_supported_locales))
logging.info("Supported locales: %s", sorted(_supported_locales))


def get_supported_locales(cls):
Expand Down

0 comments on commit ca8002f

Please sign in to comment.