From 6709ea4ae91b906742506ac0c42a3a272991001f Mon Sep 17 00:00:00 2001 From: Sergey Fursov Date: Mon, 26 Sep 2016 01:25:38 +0300 Subject: [PATCH] Fixed #27271 -- Fixed a crash in runserver logging. Allowed ServerFormatter to handle simple string messages or messages with formatting arguments. The formatter will set the server_time variable on the log record if it's required by the format string but wasn't passed in extra parameters. --- django/utils/log.py | 26 +++++++++++-------- docs/releases/1.10.2.txt | 3 +++ tests/get_or_create/tests.py | 3 ++- tests/logging_tests/tests.py | 49 +++++++++++++++++++++++++++++++++++- 4 files changed, 68 insertions(+), 13 deletions(-) diff --git a/django/utils/log.py b/django/utils/log.py index b60b9add98..2b57c6beff 100644 --- a/django/utils/log.py +++ b/django/utils/log.py @@ -164,28 +164,32 @@ class ServerFormatter(logging.Formatter): super(ServerFormatter, self).__init__(*args, **kwargs) def format(self, record): - args = record.args msg = record.msg + status_code = getattr(record, 'status_code', None) - if len(args) == 0: - msg = self.style.HTTP_BAD_REQUEST(msg) - else: - if args[1][0] == '2': + if status_code: + if 200 <= status_code < 300: # Put 2XX first, since it should be the common case msg = self.style.HTTP_SUCCESS(msg) - elif args[1][0] == '1': + elif 100 <= status_code < 200: msg = self.style.HTTP_INFO(msg) - elif args[1] == '304': + elif status_code == 304: msg = self.style.HTTP_NOT_MODIFIED(msg) - elif args[1][0] == '3': + elif 300 <= status_code < 400: msg = self.style.HTTP_REDIRECT(msg) - elif args[1] == '404': + elif status_code == 404: msg = self.style.HTTP_NOT_FOUND(msg) - elif args[1][0] == '4': + elif 400 <= status_code < 500: msg = self.style.HTTP_BAD_REQUEST(msg) else: - # Any 5XX, or any other response + # Any 5XX, or any other status code msg = self.style.HTTP_SERVER_ERROR(msg) + if self.uses_server_time() and not hasattr(record, 'server_time'): + record.server_time = self.formatTime(record, self.datefmt) + record.msg = msg return super(ServerFormatter, self).format(record) + + def uses_server_time(self): + return self._fmt.find('%(server_time)') >= 0 diff --git a/docs/releases/1.10.2.txt b/docs/releases/1.10.2.txt index 222323c245..075eb947f9 100644 --- a/docs/releases/1.10.2.txt +++ b/docs/releases/1.10.2.txt @@ -22,3 +22,6 @@ Bugfixes ``SplitDateTimeWidget``, ``SelectDateWidget``, and ``SplitArrayWidget`` (:ticket:`27186`). Custom widgets affected by this issue may need to implement a :meth:`~django.forms.Widget.value_omitted_from_data` method. + +* Fixed a crash in ``runserver`` logging during a "Broken pipe" error + (:ticket:`27271`). diff --git a/tests/get_or_create/tests.py b/tests/get_or_create/tests.py index c569d938b0..8100c305b6 100644 --- a/tests/get_or_create/tests.py +++ b/tests/get_or_create/tests.py @@ -8,7 +8,8 @@ from threading import Thread from django.core.exceptions import FieldError from django.db import DatabaseError, IntegrityError, connection from django.test import ( - SimpleTestCase, TestCase, TransactionTestCase, ignore_warnings, skipUnlessDBFeature, + SimpleTestCase, TestCase, TransactionTestCase, ignore_warnings, + skipUnlessDBFeature, ) from django.utils.encoding import DjangoUnicodeDecodeError diff --git a/tests/logging_tests/tests.py b/tests/logging_tests/tests.py index f6f1db7a6b..ca141657c8 100644 --- a/tests/logging_tests/tests.py +++ b/tests/logging_tests/tests.py @@ -3,19 +3,22 @@ from __future__ import unicode_literals import logging import warnings +from contextlib import contextmanager from admin_scripts.tests import AdminScriptTestCase from django.conf import settings from django.core import mail from django.core.files.temp import NamedTemporaryFile +from django.core.management import color from django.db import connection from django.test import RequestFactory, SimpleTestCase, override_settings from django.test.utils import LoggingCaptureMixin, patch_logger +from django.utils import six from django.utils.deprecation import RemovedInNextVersionWarning from django.utils.log import ( DEFAULT_LOGGING, AdminEmailHandler, CallbackFilter, RequireDebugFalse, - RequireDebugTrue, + RequireDebugTrue, ServerFormatter, ) from .logconfig import MyEmailBackend @@ -513,3 +516,47 @@ class SchemaLoggerTests(SimpleTestCase): }}, )] ) + + +class LogFormattersTests(SimpleTestCase): + + def test_server_formatter_styles(self): + color_style = color.make_style('') + formatter = ServerFormatter() + formatter.style = color_style + log_msg = 'log message' + status_code_styles = [ + (200, 'HTTP_SUCCESS'), + (100, 'HTTP_INFO'), + (304, 'HTTP_NOT_MODIFIED'), + (300, 'HTTP_REDIRECT'), + (404, 'HTTP_NOT_FOUND'), + (400, 'HTTP_BAD_REQUEST'), + (500, 'HTTP_SERVER_ERROR'), + ] + for status_code, style in status_code_styles: + record = logging.makeLogRecord({'msg': log_msg, 'status_code': status_code}) + self.assertEqual(formatter.format(record), getattr(color_style, style)(log_msg)) + record = logging.makeLogRecord({'msg': log_msg}) + self.assertEqual(formatter.format(record), log_msg) + + def test_server_formatter_default_format(self): + server_time = '2016-09-25 10:20:30' + log_msg = 'log message' + logger = logging.getLogger('django.server') + + @contextmanager + def patch_django_server_logger(): + old_stream = logger.handlers[0].stream + new_stream = six.StringIO() + logger.handlers[0].stream = new_stream + yield new_stream + logger.handlers[0].stream = old_stream + + with patch_django_server_logger() as logger_output: + logger.info(log_msg, extra={'server_time': server_time}) + self.assertEqual('[%s] %s\n' % (server_time, log_msg), logger_output.getvalue()) + + with patch_django_server_logger() as logger_output: + logger.info(log_msg) + six.assertRegex(self, logger_output.getvalue(), r'^\[[-:,.\s\d]+\] %s' % log_msg)