Merge lp:~rvb/maas/fix-loggers into lp:~maas-committers/maas/trunk

[Raphaël Badin]

Fix the DebuggingLoggerMiddleware. Remove the custom response_log_debug/request_log_debug config items and integrate DebuggingLoggerMiddleware with the standard logging system.

This branch does 3 things:
- it fixes bug 1227543.
- it fixes bug 1227558.
- it refactors the DebuggingLoggerMiddleware to integrate it with the standard logging system instead of using custom config items for enabling/disabling the debug output.

At first, I wanted to do this in two steps but Gavin "convinced" me to do otherwise and to do all in one branch. Anyway, the diff is not really big so I hope you won't mind.

[Gavin Panella (allenap)]

Lovely :)

review: Approve

[Julian Edwards (julian-edwards)]

On 04/10/13 01:26, Raphaël Badin wrote:
> - it refactors the DebuggingLoggerMiddleware to integrate it with the standard logging system instead of using custom config items for enabling/disabling the debug output.

How does that now allow us to use an API call to turn the debug logging
on and off?

If you removed that functionality, please put it back!

[Raphaël Badin (rvb)]

> How does that now allow us to use an API call to turn the debug logging
> on and off?

It's not there anymore, but now it uses what the rest of the code is using: the log level defined in MAAS' configuration file.

> If you removed that functionality, please put it back!

If we want this (as opposed to just doing [0]), then I think we should add an API call to change the log level.

[0]

- edit /etc/maas/maas_config to change the log level
- sudo service apache2 reload

[Julian Edwards (julian-edwards)]

On 08/10/13 17:19, Raphaël Badin wrote:
>> How does that now allow us to use an API call to turn the debug logging
>> on and off?
>
> It's not there anymore, but now it uses what the rest of the code is using: the log level defined in MAAS' configuration file.
>
>> If you removed that functionality, please put it back!
>
> If we want this (as opposed to just doing [0]), then I think we should add an API call to change the log level.
>
> [0]
>
> - edit /etc/maas/maas_config to change the log level
> - sudo service apache2 reload
>
>

Ok this needs fixing then. There are a few things I dislike:

 * editing configs
 * restarting services
 * having to configure files and restart *every appserver instance* on a
multi appserver installation

=== modified file 'src/maasserver/forms_settings.py'
--- src/maasserver/forms_settings.py	2013-09-19 13:34:46 +0000
+++ src/maasserver/forms_settings.py	2013-10-03 15:20:34 +0000
@@ -190,22 +190,6 @@
                 'invalid_choice': INVALID_DISTRO_SERIES_MESSAGE},
         }
     },
-    'request_log_debug': {
-        'default': False,
-        'form': forms.BooleanField,
-        'form_kwargs': {
-            'label': "Log the requests information (debug option)",
-            'required': False,
-        }
-    },
-    'response_log_debug': {
-        'default': False,
-        'form': forms.BooleanField,
-        'form_kwargs': {
-            'label': "Log the responses information (debug option)",
-            'required': False,
-        }
-    },
 }
 
 

=== modified file 'src/maasserver/middleware.py'
--- src/maasserver/middleware.py	2013-09-06 07:52:39 +0000
+++ src/maasserver/middleware.py	2013-10-03 15:20:34 +0000
@@ -23,6 +23,7 @@
     )
 import httplib
 import json
+import logging
 import re
 
 from django.conf import settings
@@ -38,13 +39,13 @@
     HttpResponseForbidden,
     HttpResponseRedirect,
     )
+from django.http.request import build_request_repr
 from django.utils.http import urlquote_plus
 from maasserver import logger
 from maasserver.exceptions import (
     ExternalComponentException,
     MAASAPIException,
     )
-from maasserver.models import Config
 
 
 def get_relative_path(path):
@@ -217,15 +218,28 @@
 
 class DebuggingLoggerMiddleware:
 
+    log_level = logging.DEBUG
+
     def process_request(self, request):
-        if Config.objects.get_config("request_log_debug"):
+        if logger.isEnabledFor(self.log_level):
             header = " Request dump ".center(79, "#")
-            logger.info("%s\n%r\n%s", header, request, request.content)
+            logger.log(
+                self.log_level,
+                "%s\n%s", header, build_request_repr(request))
         return None  # Allow request processing to continue unabated.
 
     def process_response(self, request, response):
-        if Config.objects.get_config("response_log_debug"):
+        if logger.isEnabledFor(self.log_level):
             header = " Response dump ".center(79, "#")
             content = getattr(response, "content", "{no content}")
-            logger.info("%s\n%r\n%s", header, response, content)
+            try:
+                decoded_content = content.decode('utf-8')
+            except UnicodeDecodeError:
+                logger.log(
+                    self.log_level,
+                    "%s\n%s", header, "** non-utf-8 (binary?) content **")
+            else:
+                logger.log(
+                    self.log_level,
+                    "%s\n%s", header, decoded_content)
         return response  # Return response unaltered.

=== modified file 'src/maasserver/models/config.py'
--- src/maasserver/models/config.py	2013-08-27 07:49:11 +0000
+++ src/maasserver/models/config.py	2013-10-03 15:20:34 +0000
@@ -54,9 +54,6 @@
         'default_distro_series': DISTRO_SERIES.precise,
         'commissioning_distro_series': DISTRO_SERIES.precise,
         'http_proxy': None,
-        # Miscellaneous configuration.
-        'request_log_debug': False,
-        'response_log_debug': False,
         ## /settings
         }
 

=== modified file 'src/maasserver/tests/test_forms_settings.py'
--- src/maasserver/tests/test_forms_settings.py	2013-09-19 13:34:46 +0000
+++ src/maasserver/tests/test_forms_settings.py	2013-10-03 15:20:34 +0000
@@ -50,20 +50,6 @@
         self.assertEqual(
             {'maas_name': maas_name}, form.initial)
 
-    def test_request_log_debug(self):
-        form = get_config_form('request_log_debug')
-        self.assertItemsEqual(['request_log_debug'], form.fields)
-        self.assertEqual(
-            forms.BooleanField,
-            form.fields['request_log_debug'].__class__)
-
-    def test_response_log_debug(self):
-        form = get_config_form('response_log_debug')
-        self.assertItemsEqual(['response_log_debug'], form.fields)
-        self.assertEqual(
-            forms.BooleanField,
-            form.fields['response_log_debug'].__class__)
-
 
 class TestGetConfigDoc(MAASServerTestCase):
 

=== modified file 'src/maasserver/tests/test_middleware.py'
--- src/maasserver/tests/test_middleware.py	2013-09-11 08:13:20 +0000
+++ src/maasserver/tests/test_middleware.py	2013-10-03 15:20:34 +0000
@@ -22,6 +22,7 @@
     ValidationError,
     )
 from django.http import HttpResponse
+from django.http.request import build_request_repr
 from django.test.client import RequestFactory
 import maasserver
 from maasserver.exceptions import (
@@ -37,13 +38,13 @@
     ExceptionLoggerMiddleware,
     ExceptionMiddleware,
     )
-from maasserver.models import Config
 from maasserver.testing import extract_redirect
 from maasserver.testing.factory import factory
 from maasserver.testing.testcase import (
     LoggedInTestCase,
     MAASServerTestCase,
     )
+from maastesting.utils import sample_binary_data
 from testtools.matchers import (
     Contains,
     FileContains,
@@ -188,6 +189,7 @@
         handler = logging.handlers.RotatingFileHandler(filename)
         logger.addHandler(handler)
         self.addCleanup(logger.removeHandler, handler)
+        return logger
 
 
 class ExceptionLoggerMiddlewareTest(LoggingTest):
@@ -207,21 +209,18 @@
     def setUp(self):
         super(LoggingTest, self).setUp()
         self.logfile = self.make_file(contents="")
-        self.set_up_logger(self.logfile)
-
-    def test_that_default_request_log_config_is_false(self):
-        self.assertFalse(Config.objects.get_config("request_log_debug"))
-
-    def test_that_default_response_log_config_is_false(self):
-        self.assertFalse(Config.objects.get_config("response_log_debug"))
-
-    def test_debugging_logger_does_not_log_request_if_config_is_false(self):
+        self.logger = self.set_up_logger(self.logfile)
+
+    def test_debugging_logger_does_not_log_request_if_info_level(self):
+        self.logger.setLevel(logging.INFO)
         request = fake_request("/api/1.0/nodes/")
         DebuggingLoggerMiddleware().process_request(request)
         self.assertThat(
-            self.logfile, Not(FileContains(matcher=Contains(repr(request)))))
+            self.logfile,
+            Not(FileContains(matcher=Contains(build_request_repr(request)))))
 
-    def test_debugging_logger_does_not_log_response_if_config_is_false(self):
+    def test_debugging_logger_does_not_log_response_if_info_level(self):
+        self.logger.setLevel(logging.INFO)
         request = fake_request("/api/1.0/nodes/")
         response = HttpResponse(
             content="test content",
@@ -229,20 +228,20 @@
             mimetype=b"text/plain; charset=utf-8")
         DebuggingLoggerMiddleware().process_response(request, response)
         self.assertThat(
-            self.logfile, Not(FileContains(matcher=Contains(repr(request)))))
+            self.logfile,
+            Not(FileContains(matcher=Contains(build_request_repr(request)))))
 
     def test_debugging_logger_logs_request(self):
-        Config.objects.set_config("request_log_debug", True)
+        self.logger.setLevel(logging.DEBUG)
         request = fake_request("/api/1.0/nodes/")
         request.content = "test content"
         DebuggingLoggerMiddleware().process_request(request)
         self.assertThat(
-            self.logfile, FileContains(matcher=Contains(repr(request))))
-        self.assertThat(
-            self.logfile, FileContains(matcher=Contains(request.content)))
+            self.logfile,
+            FileContains(matcher=Contains(build_request_repr(request))))
 
     def test_debugging_logger_logs_response(self):
-        Config.objects.set_config("response_log_debug", True)
+        self.logger.setLevel(logging.DEBUG)
         request = fake_request("foo")
         response = HttpResponse(
             content="test content",
@@ -250,10 +249,20 @@
             mimetype=b"text/plain; charset=utf-8")
         DebuggingLoggerMiddleware().process_response(request, response)
         self.assertThat(
-            self.logfile, FileContains(matcher=Contains(repr(response))))
-        self.assertThat(
             self.logfile, FileContains(matcher=Contains(response.content)))
 
+    def test_debugging_logger_logs_binary_response(self):
+        self.logger.setLevel(logging.DEBUG)
+        request = fake_request("foo")
+        response = HttpResponse(
+            content=sample_binary_data,
+            status=httplib.OK,
+            mimetype=b"application/octet-stream")
+        DebuggingLoggerMiddleware().process_response(request, response)
+        self.assertThat(
+            self.logfile,
+            FileContains(matcher=Contains("non-utf-8 (binary?) content")))
+
 
 class ErrorsMiddlewareTest(LoggedInTestCase):