From f24119edb989613d41775e68348625a820581360 Mon Sep 17 00:00:00 2001 From: tiagob Date: Tue, 10 Jun 2014 17:21:45 -0700 Subject: [PATCH] cherry pick 3258726fea5bcd1b401907653bc953ce63d5aeb2 from tornado to reduce log spam --- tornado/httpserver.py | 8 +- tornado/iostream.py | 21 ++++- tornado/test/httpserver_test.py | 146 ++++++++++++++++++++++++++++++- website/sphinx/releases/next.rst | 140 +++++++++++++++++++++++++++++ 4 files changed, 307 insertions(+), 8 deletions(-) create mode 100644 website/sphinx/releases/next.rst diff --git a/tornado/httpserver.py b/tornado/httpserver.py index 5667ba1567..68931050d9 100644 --- a/tornado/httpserver.py +++ b/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: diff --git a/tornado/iostream.py b/tornado/iostream.py index 34b677e45e..26cbcd90a5 100644 --- a/tornado/iostream.py +++ b/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: diff --git a/tornado/test/httpserver_test.py b/tornado/test/httpserver_test.py index 3b49a5026a..1d9632078c 100644 --- a/tornado/test/httpserver_test.py +++ b/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() diff --git a/website/sphinx/releases/next.rst b/website/sphinx/releases/next.rst new file mode 100644 index 0000000000..7a8880e236 --- /dev/null +++ b/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 `_ +* 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.