From 0bc5cd628042bf0a44df60a93085a4f991a84dfb Mon Sep 17 00:00:00 2001 From: Flavio Curella Date: Fri, 6 Nov 2015 10:19:41 -0600 Subject: [PATCH] Fixed #25684 -- Made runserver use logging for request/response output. Thanks andreif for the contributing to the patch. --- django/core/servers/basehttp.py | 64 +++++++++++++++------------------ django/utils/log.py | 50 ++++++++++++++++++++++++++ docs/ref/django-admin.txt | 8 +++++ docs/releases/1.10.txt | 30 ++++++++++++++++ docs/topics/logging.txt | 23 ++++++++++++ tests/servers/test_basehttp.py | 53 ++++++++++++++++++++------- 6 files changed, 180 insertions(+), 48 deletions(-) diff --git a/django/core/servers/basehttp.py b/django/core/servers/basehttp.py index b9184ca20d4..60fc09a122a 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) - else: - # Any 5XX, or any other response - msg = self.style.HTTP_SERVER_ERROR(msg) + extra['status_code'] = 500 + logger.error( + "You're accessing the development server over HTTPS, but " + "it only supports HTTP.\n", extra=extra, + ) + return - sys.stderr.write(msg) + 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: + level = logger.info + + 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 6fb487b7fc7..fcc7575180f 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 870f5dfc5ce..ca21851fe5f 100644 --- a/docs/ref/django-admin.txt +++ b/docs/ref/django-admin.txt @@ -827,6 +827,14 @@ with its own :ref:`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 f3c7669d8a4..830f11b66d8 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 be8c278d972..407f12aaef8 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 4a3ba3577e1..2d57d7c257c 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.