[EV-62] Add the ability to log timing information during paver tasks

pavelib/utils/timer.py

@@ -0,0 +1,80 @@
+"""
+Tools for timing paver tasks
+"""
+
+from datetime import datetime
+import json
+import logging
+import os
+from os.path import dirname, exists
+import sys
+import traceback
+import wrapt
+
+LOGGER = logging.getLogger(__file__)
+PAVER_TIMER_LOG = os.environ.get('PAVER_TIMER_LOG')
+
+
+@wrapt.decorator
+def timed(wrapped, instance, args, kwargs):  # pylint: disable=unused-argument
+    """
+    Log execution time for a function to a log file.
+
+    Logging is only actually executed if the PAVER_TIMER_LOG environment variable
+    is set. That variable is expanded for the current user and current
+    environment variables. It also can have :meth:`~Datetime.strftime` format
+    identifiers which are substituted using the time when the task started.
+
+    For example, ``PAVER_TIMER_LOG='~/.paver.logs/%Y-%d-%m.log'`` will create a new
+    log file every day containing reconds for paver tasks run that day, and
+    will put those log files in the ``.paver.logs`` directory inside the users
+    home.
+
+    Must be earlier in the decorator stack than the paver task declaration.
+    """
+    start = datetime.utcnow()
+    exception_info = {}
+    try:
+        return wrapped(*args, **kwargs)
+    except Exception as exc:  # pylint: disable=broad-except
+        exception_info = {
+            'exception': "".join(traceback.format_exception_only(type(exc), exc)).strip()
+        }
+        raise
+    finally:
+        end = datetime.utcnow()
+
+        # N.B. This is intended to provide a consistent interface and message format
+        # across all of Open edX tooling, so it deliberately eschews standard
+        # python logging infrastructure.
+        if PAVER_TIMER_LOG is not None:
+
+            log_path = start.strftime(PAVER_TIMER_LOG)
+
+            log_message = {
+                'python_version': sys.version,
+                'task': "{}.{}".format(wrapped.__module__, wrapped.__name__),
+                'args': [repr(arg) for arg in args],
+                'kwargs': {key: repr(value) for key, value in kwargs.items()},
+                'started_at': start.isoformat(' '),
+                'ended_at': end.isoformat(' '),
+                'duration': (end - start).total_seconds(),
+            }
+            log_message.update(exception_info)
+
+            try:
+                if not exists(dirname(log_path)):
+                    os.makedirs(dirname(log_path))
+
+                with open(log_path, 'a') as outfile:
+                    json.dump(
+                        log_message,
+                        outfile,
+                        separators=(',', ':'),
+                        sort_keys=True,
+                    )
+                    outfile.write('\n')
+            except OSError:
+                # Squelch OSErrors, because we expect them and they shouldn't
+                # interrupt the rest of the process.
+                LOGGER.exception("Unable to write timing logs")