Log spam 1038

tornado/httpserver.py

@@ -220,7 +220,13 @@ def _finish_request(self):
         if disconnect:
             self.stream.close()
             return
-        self.stream.read_until(b("\r\n\r\n"), self._header_callback)
+        try:
+            # Use a try/except instead of checking stream.closed()
+            # directly, because in some cases the stream doesn't discover
+            # that it's closed until you try to read from it.
+            self.stream.read_until(b("\r\n\r\n"), self._header_callback)
+        except iostream.StreamClosedError:
+            self.close()
 
     def _on_headers(self, data):
         try:

tornado/iostream.py

@@ -35,6 +35,13 @@
 except ImportError:
     ssl = None
 
+try:
+    from tornado.platform.posix import _set_nonblocking
+except ImportError:
+    _set_nonblocking = None
+
+class StreamClosedError(IOError):
+    pass
 
 class IOStream(object):
     r"""A utility class to write to and read from a non-blocking socket.
@@ -419,8 +426,14 @@ def _read_to_buffer(self):
             chunk = self._read_from_socket()
         except socket.error, e:
             # ssl.SSLError is a subclass of socket.error
-            logging.warning("Read error on %d: %s",
-                            self.socket.fileno(), e)
+            if e.args[0] == errno.ECONNRESET:
+                # Treat ECONNRESET as a connection close rather than
+                # an error to minimize log spam  (the exception will
+                # be available on self.error for apps that care).
+                self.close()
+                return
+            gen_log.warning("Read error on %d: %s",
+                            self.fileno(), e)
             self.close()
             raise
         if chunk is None:
@@ -558,8 +571,8 @@ def _consume(self, loc):
         return self._read_buffer.popleft()
 
     def _check_closed(self):
-        if not self.socket:
-            raise IOError("Stream is closed")
+        if self.closed():
+            raise StreamClosedError("Stream is closed")
 
     def _maybe_add_error_listener(self):
         if self._state is None and self._pending_callbacks == 0:

tornado/test/httpserver_test.py

@@ -10,7 +10,8 @@
 from tornado.simple_httpclient import SimpleAsyncHTTPClient
 from tornado.testing import AsyncHTTPTestCase, LogTrapTestCase, AsyncTestCase
 from tornado.util import b, bytes_type
-from tornado.web import Application, RequestHandler
+from tornado.web import Application, RequestHandler, asynchronous
+import datetime
 import os
 import shutil
 import socket
@@ -406,5 +407,144 @@ def test_unix_socket(self):
         stream.close()
         server.stop()
 
-if not hasattr(socket, 'AF_UNIX') or sys.platform == 'cygwin':
-    del UnixSocketTest
+UnixSocketTest = unittest.skipIf(
+    not hasattr(socket, 'AF_UNIX') or sys.platform == 'cygwin',
+    "unix sockets not supported on this platform")
+
+class KeepAliveTest(AsyncHTTPTestCase):
+    """Tests various scenarios for HTTP 1.1 keep-alive support.
+
+    These tests don't use AsyncHTTPClient because we want to control
+    connection reuse and closing.
+    """
+    def get_app(self):
+        test = self
+
+        class HelloHandler(RequestHandler):
+            def get(self):
+                self.finish('Hello world')
+
+        class LargeHandler(RequestHandler):
+            def get(self):
+                # 512KB should be bigger than the socket buffers so it will
+                # be written out in chunks.
+                self.write(''.join(chr(i % 256) * 1024 for i in xrange(512)))
+
+        class FinishOnCloseHandler(RequestHandler):
+            @asynchronous
+            def get(self):
+                self.flush()
+
+            def on_connection_close(self):
+                # This is not very realistic, but finishing the request
+                # from the close callback has the right timing to mimic
+                # some errors seen in the wild.
+                self.finish('closed')
+
+        return Application([('/', HelloHandler),
+                            ('/large', LargeHandler),
+                            ('/finish_on_close', FinishOnCloseHandler)])
+
+    def setUp(self):
+        super(KeepAliveTest, self).setUp()
+        self.http_version = b('HTTP/1.1')
+
+    def tearDown(self):
+        # We just closed the client side of the socket; let the IOLoop run
+        # once to make sure the server side got the message.
+        self.io_loop.add_timeout(datetime.timedelta(seconds=0.001), self.stop)
+        self.wait()
+
+        if hasattr(self, 'stream'):
+            self.stream.close()
+        super(KeepAliveTest, self).tearDown()
+
+    # The next few methods are a crude manual http client
+    def connect(self):
+        self.stream = IOStream(socket.socket(), io_loop=self.io_loop)
+        self.stream.connect(('localhost', self.get_http_port()), self.stop)
+        self.wait()
+
+    def read_headers(self):
+        self.stream.read_until(b('\r\n'), self.stop)
+        first_line = self.wait()
+        self.assertTrue(first_line.startswith(self.http_version + b(' 200')), first_line)
+        self.stream.read_until(b('\r\n\r\n'), self.stop)
+        header_bytes = self.wait()
+        headers = HTTPHeaders.parse(header_bytes.decode('latin1'))
+        return headers
+
+    def read_response(self):
+        headers = self.read_headers()
+        self.stream.read_bytes(int(headers['Content-Length']), self.stop)
+        body = self.wait()
+        self.assertEqual(b('Hello world'), body)
+
+    def close(self):
+        self.stream.close()
+        del self.stream
+
+    def test_two_requests(self):
+        self.connect()
+        self.stream.write(b('GET / HTTP/1.1\r\n\r\n'))
+        self.read_response()
+        self.stream.write(b('GET / HTTP/1.1\r\n\r\n'))
+        self.read_response()
+        self.close()
+
+    def test_request_close(self):
+        self.connect()
+        self.stream.write(b('GET / HTTP/1.1\r\nConnection: close\r\n\r\n'))
+        self.read_response()
+        self.stream.read_until_close(callback=self.stop)
+        data = self.wait()
+        self.assertTrue(not data)
+        self.close()
+
+    # keepalive is supported for http 1.0 too, but it's opt-in
+    def test_http10(self):
+        self.http_version = b('HTTP/1.0')
+        self.connect()
+        self.stream.write(b('GET / HTTP/1.0\r\n\r\n'))
+        self.read_response()
+        self.stream.read_until_close(callback=self.stop)
+        data = self.wait()
+        self.assertTrue(not data)
+        self.close()
+
+    def test_http10_keepalive(self):
+        self.http_version = b('HTTP/1.0')
+        self.connect()
+        self.stream.write(b('GET / HTTP/1.0\r\nConnection: keep-alive\r\n\r\n'))
+        self.read_response()
+        self.stream.write(b('GET / HTTP/1.0\r\nConnection: keep-alive\r\n\r\n'))
+        self.read_response()
+        self.close()
+
+    def test_pipelined_requests(self):
+        self.connect()
+        self.stream.write(b('GET / HTTP/1.1\r\n\r\nGET / HTTP/1.1\r\n\r\n'))
+        self.read_response()
+        self.read_response()
+        self.close()
+
+    def test_pipelined_cancel(self):
+        self.connect()
+        self.stream.write(b('GET / HTTP/1.1\r\n\r\nGET / HTTP/1.1\r\n\r\n'))
+        # only read once
+        self.read_response()
+        self.close()
+
+    def test_cancel_during_download(self):
+        self.connect()
+        self.stream.write(b('GET /large HTTP/1.1\r\n\r\n'))
+        self.read_headers()
+        self.stream.read_bytes(1024, self.stop)
+        self.wait()
+        self.close()
+
+    def test_finish_while_closed(self):
+        self.connect()
+        self.stream.write(b('GET /finish_on_close HTTP/1.1\r\n\r\n'))
+        self.read_headers()
+        self.close()

website/sphinx/releases/next.rst

@@ -0,0 +1,140 @@
+What's new in the next release of Tornado
+=========================================
+
+In progress
+-----------
+
+* The Tornado test suite now requires ``unittest2`` when run on Python 2.5
+  or 2.6.
+* `tornado.testing.AsyncTestCase` and friends now extend ``unittest2.TestCase``
+  when it is available (and continue to use the standard ``unittest`` module
+  when ``unittest2`` is not available)
+* `tornado.netutil.bind_sockets` no longer sets ``AI_ADDRCONFIG``; this will
+  cause it to bind to both ipv4 and ipv6 more often than before.
+* `tornado.netutil.bind_sockets` has a new ``flags`` argument that can
+  be used to pass additional flags to ``getaddrinfo``.
+* Tornado no longer logs to the root logger.  Details on the new logging
+  scheme can be found under the `tornado.log` module.  Note that in some
+  cases this will require that you add an explicit logging configuration
+  in ordre to see any output (perhaps just calling ``logging.basicConfig()``),
+  although both `IOLoop.start()` and `tornado.options.parse_command_line`
+  will do this for you.
+* Errors while rendering templates no longer log the generated code,
+  since the enhanced stack traces (from version 2.1) should make this
+  unnecessary.
+* `tornado.testing.ExpectLog` can be used as a finer-grained alternative
+  to `tornado.testing.LogTrapTestCase`
+* The command-line interface to `tornado.testing.main` now supports
+  additional arguments from the underlying `unittest` module:
+  ``verbose``, ``quiet``, ``failfast``, ``catch``, ``buffer``.
+* Empty HTTP request arguments are no longer ignored.  This applies to
+  ``HTTPRequest.arguments`` and ``RequestHandler.get_argument[s]``
+  in WSGI and non-WSGI modes.
+* New function `tornado.testing.bind_unused_port` both chooses a port
+  and binds a socket to it, so there is no risk of another process
+  using the same port.  ``get_unused_port`` is now deprecated.
+* The `tornado.database` module has been removed.  It is now available
+  as a separate package, `torndb <https://github.com/bdarnell/torndb>`_
+* New class `tornado.iostream.PipeIOStream` provides the IOStream
+  interface on pipe file descriptors.
+* Much of `IOStream` has been refactored into a separate class
+  `BaseIOStream`.
+* New class `tornado.process.Subprocess` wraps `subprocess.Popen` with
+  `PipeIOStream` access to the child's file descriptors.
+* `IOLoop` now uses `signal.set_wakeup_fd` where available (Python 2.6+
+  on Unix) to avoid a race condition that could result in Python signal
+  handlers being delayed.
+* `WebSocketHandler` has new methods `ping` and `on_pong` to send pings
+  to the browser (not supported on the ``draft76`` protocol)
+* The ``Date`` HTTP header is now set by default on all responses.
+* Several methods related to HTTP status codes now take a ``reason`` keyword
+  argument to specify an alternate "reason" string (i.e. the "Not Found" in
+  "HTTP/1.1 404 Not Found").  It is now possible to set status codes other
+  than those defined in the spec, as long as a reason string is given.
+* New method `IOLoop.add_callback_from_signal` is safe to use in a signal
+  handler (the regular `add_callback` method may deadlock).
+* `stack_context.wrap` now runs the wrapped callback in a more consistent
+  environment by recreating contexts even if they already exist on the
+  stack.
+* Fixed a bug in which stack contexts could leak from one callback
+  chain to another.
+* `tornado.autoreload` is now more reliable when there are errors at import
+  time.
+* New optional dependency on `concurrent.futures` to provide better support
+  for working with threads.  `concurrent.futures` is in the standard library
+  for Python 3.2+, and can be installed on older versions with
+  ``pip install futures``.
+* New module `tornado.concurrent` contains code to support working with
+  `concurrent.futures`, or to emulate future-based interface when that module
+  is not available.
+* New method `IOLoop.add_future` to run a callback on the IOLoop when
+  an asynchronous ``Future`` finishes.
+* New class `tornado.netutil.Resolver` provides an asynchronous
+  interface to `socket.getaddrinfo`.  The interface is based on (but
+  does not require) `concurrent.futures`.  When used with
+  `concurrent.futures.ThreadPoolExecutor`, it allows for DNS
+  resolution without blocking the main thread.
+* `SimpleAsyncHTTPClient` now takes a ``resolver`` keyword argument (which
+  may be passed to either the constructor or ``configure``), to allow it to
+  use the new non-blocking `tornado.netutil.Resolver`.
+* Functions using `gen.engine` may now yield ``Future`` objects.
+* New function `IOLoop.current` returns the ``IOLoop`` that is running
+  on the current thread (as opposed to `IOLoop.instance`, which returns a
+  specific thread's (usually the main thread's) IOLoop).
+* `tornado.options.parse_config_file` now configures logging automatically
+  by default, in the same way that `parse_command_line` does.
+* New function `tornado.options.add_parse_callback` schedules a callback
+  to be run after the command line or config file has been parsed.  The
+  keyword argument ``final=False`` can be used on either parsing function
+  to supress these callbacks.
+* Function `tornado.options.enable_pretty_logging` has been moved to the
+  `tornado.log` module.
+* `tornado.options.define` now takes a ``callback`` argument.  This callback
+  will be run with the new value whenever the option is changed.  This is
+  especially useful for options that set other options, such as by reading
+  from a config file.
+* `tornado.option.parse_command_line` ``--help`` output now goes to ``stderr``
+  rather than ``stdout``.
+* The class underlying the functions in `tornado.options` is now public
+  (`tornado.options.OptionParser`).  This can be used to create multiple
+  independent option sets, such as for subcommands.
+* `tornado.options.options` is no longer a subclass of `dict`; attribute-style
+  access is now required.
+* The ``max_clients`` argument to `AsyncHTTPClient` is now a keyword-only
+  argument.
+* Keyword arguments to `AsyncHTTPClient.configure` are no longer used
+  when instantiating an implementation subclass directly.
+* The `IOLoop` poller implementations (``select``, ``epoll``, ``kqueue``)
+  are now available as distinct subclasses of `IOLoop`.  Instantiating
+  `IOLoop` will continue to automatically choose the best available
+  implementation.
+* `IOLoop` now has a static ``configure`` method like the one on
+  `AsyncHTTPClient`, which can be used to select an IOLoop implementation
+  other than the default.
+* The deprecated ``--autoreload`` option of `tornado.testing.main` has
+  been removed.  Use ``python -m tornado.autoreload`` as a prefix command
+  instead.
+* The ``--httpclient`` option of `tornado.testing.main` has been moved
+  to `tornado.test.runtests` so as not to pollute the application
+  option namespace.  The `tornado.options` module's new callback
+  support now makes it easy to add options from a wrapper script
+  instead of putting all possible options in `tornado.testing.main`.
+* The `IOLoop` constructor has a new keyword argument ``time_func``,
+  which can be used to set the time function used when scheduling callbacks.
+  This is most useful with the `time.monotonic()` function, introduced
+  in Python 3.3 and backported to older versions via the ``monotime``
+  module.  Using a monotonic clock here avoids problems when the system
+  clock is changed.
+* New function `IOLoop.time` returns the current time according to the
+  IOLoop.  To use the new monotonic clock functionality, all calls to
+  `IOLoop.add_timeout` must be either pass a `datetime.timedelta` or
+  a time relative to `IOLoop.time`, not `time.time`.  (`time.time` will
+  continue to work only as long as the IOLoop's ``time_func`` argument
+  is not used).
+* `IOStream` now raises a new exception
+  `tornado.iostream.StreamClosedException` when you attempt to read or
+  write after the stream has been closed (by either side).
+* `IOStream` now simply closes the connection when it gets an
+  ``ECONNRESET`` error, rather than logging it as an error.
+* `HTTPServer` no longer logs an error when it is unable to read a second
+  request from an HTTP 1.1 keep-alive connection.