Submitter:	Christian Hammond	Reviewers
Branch:	trunk	Groups:	reviewboard
Bugs:		People:
Change Number:	None	Repository:	Navi

Description:

This adds a new piece of Middleware to Djblets that provides logging and profiling functionality. Or to be more specific, this defines loggers for use in Python's native logging module.

On the first request, we create a logger for writing to a file, as defined by the settings of the project. If in DEBUG mode, we also define a logger to show all output on the console.

A third logger is used for writing profile information, if the LOGGING_ALLOW_PROFILING option is set to True and a ?profiling=1 parameter is passed to the URL. This can be useful during development to help optimize applications.

This also introduces a useful log_timed function that displays log messages for the beginning and end of an operation, shows the start and end times (using the native logging functionality), and then shows a warning or a critical log message depending on how long the operation takes.

Testing Done:

Tested all features with my upcoming corresponding change in Review Board.

Diff revision 1 (Latest)

Files Changed:

/trunk/djblets/djblets/logging/__init__.py: 1 change [ new content ]
/trunk/djblets/djblets/logging/middleware.py: 1 change [ new content ]
/trunk/djblets/djblets/util/misc.py: 2 changes [ 1 2 ]

Expand changes

 from datetime import datetime
 import logging
 class TimedLogInfo(object):
     """
     A utility class created by ``log_timed`` that handles the timed logging
     functionality and provides a way to end the timed logging operation.
     """
     def __init__(self, message, warning_at, critical_at, default_level,
                  log_beginning):
         self.message = message
         self.warning_at = warning_at
         self.critical_at = critical_at
         self.default_level = default_level
         self.start_time = datetime.now()
         if log_beginning:
             logging.log(self.default_level, "Begin: %s" % self.message)
     def done(self):
         """
         Stops the timed logging operation. The resulting time of the
         operation will be written to the log file. The log level depends
         on how long the operation takes.
         """
         delta = datetime.now() - self.start_time
         level = self.default_level
         if delta.seconds >= self.critical_at:
             level = logging.CRITICAL
         elif delta.seconds >= self.warning_at:
             level = logging.WARNING
         logging.log(self.default_level, "End: %s" % self.message)
         logging.log(level, "%s took %s.%s seconds" % (self.message,
                                                       delta.seconds,
                                                       delta.microseconds))
 def log_timed(message, warning_at=5, critical_at=15,
               log_beginning=True, default_level=logging.DEBUG):
     """
     Times an operation, displaying a log message before and after the
     operation. The log level for the final log message containing the
     operation runtime will be based on the runtime, the ``warning_at`` and
     the ``critical_at`` parameters.
     """
     return TimedLogInfo(message, warning_at, critical_at, default_level,
                         log_beginning)

 from datetime import datetime
 import logging
 import os.path
 import sys
 from django.conf import settings
 _logging_setup = False
 _profile_log = None
 class LoggingMiddleware(object):
     """
     A piece of middleware that sets up logging.
     This a few settings to configure.
     LOGGING_ENABLED
     ---------------
     Default: False
     Sets whether or not logging is enabled.
     LOGGING_DIRECTORY
     -----------------
     Default: None
     Specifies the directory that log files should be stored in.
     This directory must be writable by the process running Django.
     LOGGING_NAME
     ------------
     Default: None
     The name of the log files, excluding the extension and path. This will
     usually be the name of the website or web application. The file extension
     will be automatically appended when the file is written.
     LOGGING_ALLOW_PROFILING
     -----------------------
     Default: False
     Specifies whether or not code profiling is allowed. If True, visiting
     any page with a ``?profiling=1`` parameter in the URL will cause the
     request to be profiled and stored in a ``.prof`` file using the defined
     ``LOGGING_DIRECTORY`` and ``LOGGING_NAME``.
     LOGGING_LINE_FORMAT
     -------------------
     Default: "%(asctime)s - %(levelname)s - %(message)s"
     The format for lines in the log file. See Python's logging documentation
     for possible values in the format string.
     LOGGING_LEVEL
     -------------
     Default: "DEBUG"
     The minimum level to log. Possible values are ``DEBUG``, ``INFO``,
     ``WARNING``, ``ERROR`` and ``CRITICAL``.
     """
     DEFAULT_LOG_LEVEL = "DEBUG"
     DEFAULT_LINE_FORMAT = "%(asctime)s - %(levelname)s - %(message)s"
     def process_request(self, request):
         """
         Processes an incoming request. This will set up logging.
         """
         self.ensure_loggers()
     def process_view(self, request, callback, callback_args, callback_kwargs):
         """
         Handler for processing a view. This will run the profiler on the view
         if profiling is allowed in the settings and the user specified the
         profiling parameter on the URL.
         """
         if ('profiling' in request.GET and
             getattr(settings, "LOGGING_ALLOW_PROFILING", False)):
             import cProfile
             self.profiler = cProfile.Profile()
             args = (request,) + callback_args
             return self.profiler.runcall(callback, *args, **callback_kwargs)
     def process_response(self, request, response):
         """
         Handler for processing a response. Dumps the profiling information
         to the profile log file.
         """
         if ('profiling' in request.GET and
             getattr(settings, "LOGGING_ALLOW_PROFILING", False)):
             self.ensure_profile_logger()
             from cStringIO import StringIO
             self.profiler.create_stats()
             # Capture the stats
             out = StringIO()
             old_stdout, sys.stdout = sys.stdout, out
             self.profiler.print_stats(1)
             sys.stdout = old_stdout
             _profile_log.log(logging.INFO,
                              "Profiling results for %s (HTTP %s):",
                              request.path, request.method)
             _profile_log.log(logging.INFO, out.getvalue().strip())
         return response
     def ensure_loggers(self):
         """
         Sets up the main loggers, if they haven't already been set up.
         """
         global _logging_setup
         if _logging_setup:
             return
         enabled = getattr(settings, 'LOGGING_ENABLED', False)
         log_directory = getattr(settings, 'LOGGING_DIRECTORY', None)
         log_name = getattr(settings, 'LOGGING_NAME', None)
         if not enabled or not log_directory or not log_name:
             return
         log_level_name = getattr(settings, 'LOGGING_LEVEL',
                                  self.DEFAULT_LOG_LEVEL)
         log_level = logging.getLevelName(log_level_name)
         format_str = getattr(settings, 'LOGGING_LINE_FORMAT',
                              self.DEFAULT_LINE_FORMAT)
         log_path = os.path.join(log_directory, log_name + ".log")
         logging.basicConfig(
             level=log_level,
             format=format_str,
             filename=log_path,
             filemode='a'
+        )
         if settings.DEBUG:
             # In DEBUG mode, log to the console as well.
             console_log = logging.StreamHandler()
             console_log.setLevel(log_level)
             console_log.setFormatter(logging.Formatter(format_str))
             logging.getLogger('').addHandler(console_log)
         logging.info("Logging to %s with a minimum level of %s",
                      log_path, log_level_name)
         _logging_setup = True
     def ensure_profile_logger(self):
         """
         Sets up the profiling logger, if it hasn't already been set up.
         """
         global _profile_log
         enabled = getattr(settings, 'LOGGING_ENABLED', False)
         log_directory = getattr(settings, 'LOGGING_DIRECTORY', None)
         log_name = getattr(settings, 'LOGGING_NAME', None)
         if (enabled and log_directory and log_name and not _profile_log and
             getattr(settings, "LOGGING_ALLOW_PROFILING", False)):
             handler = logging.FileHandler(
                 os.path.join(log_directory, log_name + ".prof"))
             handler.setLevel(logging.INFO)
             handler.setFormatter(logging.Formatter("%(asctime)s %(message)s"))
             _profile_log = logging.getLogger("profile")
             _profile_log.addHandler(handler)

 # TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION WITH THE
 # SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
+#
 import logging
 from django.core.cache import cache
 from django.conf import settings
 from django.conf.urls.defaults import url
 from django.contrib.sites.models import Site
 from django.db.models.manager import Manager
         pass
     if not force_overwrite and cache.has_key(key):
         return cache.get(key)
     data = lookup_callable()
     # Most people will be using memcached, and memcached has a limit of 1MB.
     # Data this big should be broken up somehow, so let's warn about this.
     if len(data) >= 1024 * 1024:
         logging.warning("Cache data for key %s (length %s) may be too big "
                         "for the cache." % (key, len(data)))
     try:
         cache.set(key, data, expiration)
     except:
         pass
     return data

/trunk/djblets/djblets/logging/__init__.py: 1 change [ new content ]
/trunk/djblets/djblets/logging/middleware.py: 1 change [ new content ]
/trunk/djblets/djblets/util/misc.py: 2 changes [ 1 2 ]

Review Board

beta

This change has been marked as submitted.

Add logging/profiling support to Djblets

Diff revision 1 (Latest)

Other reviews

Your comment