Fixed #25684 -- Made runserver use logging for request/response output.

Thanks andreif for the contributing to the patch.

6 files changed, 179 insertions, 47 deletions

diff --git a/django/core/servers/basehttp.py b/django/core/servers/basehttp.py
index b9184ca20d..60fc09a122 100644
--- a/django/core/servers/basehttp.py
+++ b/django/core/servers/basehttp.py
@@ -9,13 +9,13 @@ been reviewed for security issues. DON'T USE IT FOR PRODUCTION USE!
 
 from __future__ import unicode_literals
 
+import logging
 import socket
 import sys
 from wsgiref import simple_server
 
 from django.core.exceptions import ImproperlyConfigured
 from django.core.handlers.wsgi import ISO_8859_1, UTF_8
-from django.core.management.color import color_style
 from django.core.wsgi import get_wsgi_application
 from django.utils import six
 from django.utils.encoding import uri_to_iri
@@ -24,6 +24,8 @@ from django.utils.six.moves import socketserver
 
 __all__ = ('WSGIServer', 'WSGIRequestHandler')
 
+logger = logging.getLogger('django.server')
+
 
 def get_internal_wsgi_application():
     """
@@ -80,7 +82,7 @@ class WSGIServer(simple_server.WSGIServer, object):
 
     def handle_error(self, request, client_address):
         if is_broken_pipe_error():
-            sys.stderr.write("- Broken pipe from %s\n" % (client_address,))
+            logger.info("- Broken pipe from %s\n", client_address)
         else:
             super(WSGIServer, self).handle_error(request, client_address)
 
@@ -94,47 +96,39 @@ class ServerHandler(simple_server.ServerHandler, object):
 
 
 class WSGIRequestHandler(simple_server.WSGIRequestHandler, object):
-
-    def __init__(self, *args, **kwargs):
-        self.style = color_style()
-        super(WSGIRequestHandler, self).__init__(*args, **kwargs)
-
     def address_string(self):
         # Short-circuit parent method to not call socket.getfqdn
         return self.client_address[0]
 
     def log_message(self, format, *args):
-
-        msg = "[%s] " % self.log_date_time_string()
-        try:
-            msg += "%s\n" % (format % args)
-        except UnicodeDecodeError:
-            # e.g. accessing the server via SSL on Python 2
-            msg += "\n"
-
-        # Utilize terminal colors, if available
-        if args[1][0] == '2':
-            # Put 2XX first, since it should be the common case
-            msg = self.style.HTTP_SUCCESS(msg)
-        elif args[1][0] == '1':
-            msg = self.style.HTTP_INFO(msg)
-        elif args[1] == '304':
-            msg = self.style.HTTP_NOT_MODIFIED(msg)
-        elif args[1][0] == '3':
-            msg = self.style.HTTP_REDIRECT(msg)
-        elif args[1] == '404':
-            msg = self.style.HTTP_NOT_FOUND(msg)
-        elif args[1][0] == '4':
+        extra = {
+            'request': self.request,
+            'server_time': self.log_date_time_string(),
+        }
+        if args[1][0] == '4':
             # 0x16 = Handshake, 0x03 = SSL 3.0 or TLS 1.x
             if args[0].startswith(str('\x16\x03')):
-                msg = ("You're accessing the development server over HTTPS, "
-                    "but it only supports HTTP.\n")
-            msg = self.style.HTTP_BAD_REQUEST(msg)
+                extra['status_code'] = 500
+                logger.error(
+                    "You're accessing the development server over HTTPS, but "
+                    "it only supports HTTP.\n", extra=extra,
+                )
+                return
+
+        if args[1].isdigit() and len(args[1]) == 3:
+            status_code = int(args[1])
+            extra['status_code'] = status_code
+
+            if status_code >= 500:
+                level = logger.error
+            elif status_code >= 400:
+                level = logger.warning
+            else:
+                level = logger.info
         else:
-            # Any 5XX, or any other response
-            msg = self.style.HTTP_SERVER_ERROR(msg)
+            level = logger.info
 
-        sys.stderr.write(msg)
+        level(format, *args, extra=extra)
 
     def get_environ(self):
         # Strip all headers with underscores in the name before constructing
diff --git a/django/utils/log.py b/django/utils/log.py
index 6fb487b7fc..fcc7575180 100644
--- a/django/utils/log.py
+++ b/django/utils/log.py
@@ -9,6 +9,7 @@ from copy import copy
 from django.conf import settings
 from django.core import mail
 from django.core.mail import get_connection
+from django.core.management.color import color_style
 from django.utils.deprecation import RemovedInNextVersionWarning
 from django.utils.module_loading import import_string
 from django.views.debug import ExceptionReporter
@@ -28,12 +29,23 @@ DEFAULT_LOGGING = {
             '()': 'django.utils.log.RequireDebugTrue',
         },
     },
+    'formatters': {
+        'django.server': {
+            '()': 'django.utils.log.ServerFormatter',
+            'format': '[%(server_time)s] %(message)s',
+        }
+    },
     'handlers': {
         'console': {
             'level': 'INFO',
             'filters': ['require_debug_true'],
             'class': 'logging.StreamHandler',
         },
+        'django.server': {
+            'level': 'INFO',
+            'class': 'logging.StreamHandler',
+            'formatter': 'django.server',
+        },
         'mail_admins': {
             'level': 'ERROR',
             'filters': ['require_debug_false'],
@@ -45,6 +57,11 @@ DEFAULT_LOGGING = {
             'handlers': ['console', 'mail_admins'],
             'level': 'INFO',
         },
+        'django.server': {
+            'handlers': ['django.server'],
+            'level': 'INFO',
+            'propagate': False,
+        },
         'py.warnings': {
             'handlers': ['console'],
         },
@@ -155,3 +172,36 @@ class RequireDebugFalse(logging.Filter):
 class RequireDebugTrue(logging.Filter):
     def filter(self, record):
         return settings.DEBUG
+
+
+class ServerFormatter(logging.Formatter):
+    def __init__(self, *args, **kwargs):
+        self.style = color_style()
+        super(ServerFormatter, self).__init__(*args, **kwargs)
+
+    def format(self, record):
+        args = record.args
+        msg = record.msg
+
+        if len(args) == 0:
+            msg = self.style.HTTP_BAD_REQUEST(msg)
+        else:
+            if args[1][0] == '2':
+                # Put 2XX first, since it should be the common case
+                msg = self.style.HTTP_SUCCESS(msg)
+            elif args[1][0] == '1':
+                msg = self.style.HTTP_INFO(msg)
+            elif args[1] == '304':
+                msg = self.style.HTTP_NOT_MODIFIED(msg)
+            elif args[1][0] == '3':
+                msg = self.style.HTTP_REDIRECT(msg)
+            elif args[1] == '404':
+                msg = self.style.HTTP_NOT_FOUND(msg)
+            elif args[1][0] == '4':
+                msg = self.style.HTTP_BAD_REQUEST(msg)
+            else:
+                # Any 5XX, or any other response
+                msg = self.style.HTTP_SERVER_ERROR(msg)
+
+        record.msg = msg
+        return super(ServerFormatter, self).format(record)
diff --git a/docs/ref/django-admin.txt b/docs/ref/django-admin.txt
index 870f5dfc5c..ca21851fe5 100644
--- a/docs/ref/django-admin.txt
+++ b/docs/ref/django-admin.txt
@@ -827,6 +827,14 @@ with its own :ref:`runserver<staticfiles-runserver>` command.
 If :djadmin:`migrate` was not previously executed, the table that stores the
 history of migrations is created at first run of ``runserver``.
 
+Logging of each request and response of the server is sent to the
+:ref:`django-server-logger` logger.
+
+.. versionchanged:: 1.10
+
+    In older versions, log messages were written to ``sys.stderr`` instead of
+    being handled through Python logging.
+
 .. django-admin-option:: --noreload
 
 Use the ``--noreload`` option to disable the use of the auto-reloader. This
diff --git a/docs/releases/1.10.txt b/docs/releases/1.10.txt
index f3c7669d8a..830f11b66d 100644
--- a/docs/releases/1.10.txt
+++ b/docs/releases/1.10.txt
@@ -397,6 +397,36 @@ Dropped support for PostgreSQL 9.1
 Upstream support for PostgreSQL 9.1 ends in September 2016. As a consequence,
 Django 1.10 sets PostgreSQL 9.2 as the minimum version it officially supports.
 
+``runserver`` output goes through logging
+~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
+
+Request and response handling of the ``runserver`` command is sent to the
+:ref:`django-server-logger` logger instead of to ``sys.stderr``. If you
+disable Django's logging configuration or override it with your own, you'll
+need to add the appropriate logging configuration if you want to see that
+output::
+
+    'formatters': {
+        'django.server': {
+            '()': 'django.utils.log.ServerFormatter',
+            'format': '[%(server_time)s] %(message)s',
+        }
+    },
+    'handlers': {
+        'django.server': {
+            'level': 'INFO',
+            'class': 'logging.StreamHandler',
+            'formatter': 'django.server',
+        },
+    },
+    'loggers': {
+        'django.server': {
+            'handlers': ['django.server'],
+            'level': 'INFO',
+            'propagate': False,
+        }
+    }
+
 Miscellaneous
 ~~~~~~~~~~~~~
 
diff --git a/docs/topics/logging.txt b/docs/topics/logging.txt
index be8c278d97..407f12aaef 100644
--- a/docs/topics/logging.txt
+++ b/docs/topics/logging.txt
@@ -484,6 +484,24 @@ Messages to this logger have the following extra context:
 * ``request``: The request object that generated the logging
   message.
 
+.. _django-server-logger:
+
+``django.server``
+~~~~~~~~~~~~~~~~~
+
+.. versionadded:: 1.10
+
+Log messages related to the handling of requests received by the server invoked
+by the :djadmin:`runserver` command. HTTP 5XX responses are logged as ``ERROR``
+messages, 4XX responses are logged as ``WARNING`` messages, and everything else
+is logged as ``INFO``.
+
+Messages to this logger have the following extra context:
+
+* ``status_code``: The HTTP response code associated with the request.
+
+* ``request``: The request object that generated the logging message.
+
 .. _django-template-logger:
 
 ``django.template``
@@ -729,6 +747,11 @@ When :setting:`DEBUG` is ``False``:
 * The ``django`` logger send messages with ``ERROR`` or ``CRITICAL`` level to
   :class:`AdminEmailHandler`.
 
+Independent of the value of :setting:`DEBUG`:
+
+* The :ref:`django-server-logger` logger sends all messages at the ``INFO``
+  level or higher to the console.
+
 .. versionchanged:: 1.9
 
     Django's default logging configuration changed. See :ref:`the release notes
diff --git a/tests/servers/test_basehttp.py b/tests/servers/test_basehttp.py
index 4a3ba3577e..2d57d7c257 100644
--- a/tests/servers/test_basehttp.py
+++ b/tests/servers/test_basehttp.py
@@ -1,10 +1,11 @@
+import logging
 from io import BytesIO
 
 from django.core.handlers.wsgi import WSGIRequest
 from django.core.servers.basehttp import WSGIRequestHandler
 from django.test import SimpleTestCase
 from django.test.client import RequestFactory
-from django.test.utils import captured_stderr
+from django.test.utils import captured_stderr, patch_logger
 
 
 class Stub(object):
@@ -15,13 +16,39 @@ class Stub(object):
 class WSGIRequestHandlerTestCase(SimpleTestCase):
 
     def test_log_message(self):
-        request = WSGIRequest(RequestFactory().get('/').environ)
-        request.makefile = lambda *args, **kwargs: BytesIO()
-        handler = WSGIRequestHandler(request, '192.168.0.2', None)
+        # Silence the django.server logger by replacing its StreamHandler with
+        # NullHandler.
+        logger = logging.getLogger('django.server')
+        original_handlers = logger.handlers
+        logger.handlers = [logging.NullHandler()]
+        try:
+            request = WSGIRequest(RequestFactory().get('/').environ)
+            request.makefile = lambda *args, **kwargs: BytesIO()
+            handler = WSGIRequestHandler(request, '192.168.0.2', None)
+            level_status_codes = {
+                'info': [200, 301, 304],
+                'warning': [400, 403, 404],
+                'error': [500, 503],
+            }
 
-        with captured_stderr() as stderr:
-            handler.log_message('GET %s %s', 'A', 'B')
-        self.assertIn('] GET A B', stderr.getvalue())
+            def _log_level_code(level, status_code):
+                with patch_logger('django.server', level) as messages:
+                    handler.log_message('GET %s %s', 'A', str(status_code))
+                return messages
+
+            for level, status_codes in level_status_codes.items():
+                for status_code in status_codes:
+                    # The correct level gets the message.
+                    messages = _log_level_code(level, status_code)
+                    self.assertIn('GET A %d' % status_code, messages[0])
+
+                    # Incorrect levels shouldn't have any messages.
+                    for wrong_level in level_status_codes.keys():
+                        if wrong_level != level:
+                            messages = _log_level_code(wrong_level, status_code)
+                            self.assertEqual(len(messages), 0)
+        finally:
+            logger.handlers = original_handlers
 
     def test_https(self):
         request = WSGIRequest(RequestFactory().get('/').environ)
@@ -29,13 +56,13 @@ class WSGIRequestHandlerTestCase(SimpleTestCase):
 
         handler = WSGIRequestHandler(request, '192.168.0.2', None)
 
-        with captured_stderr() as stderr:
+        with patch_logger('django.server', 'error') as messages:
             handler.log_message("GET %s %s", str('\x16\x03'), "4")
-            self.assertIn(
-                "You're accessing the development server over HTTPS, "
-                "but it only supports HTTP.",
-                stderr.getvalue()
-            )
+        self.assertIn(
+            "You're accessing the development server over HTTPS, "
+            "but it only supports HTTP.",
+            messages[0]
+        )
 
     def test_strips_underscore_headers(self):
         """WSGIRequestHandler ignores headers containing underscores.