Merge pull request #13110 from cpennington/fix-paver-timing

Fix paver timing

pavelib/acceptance_test.py

@@ -4,6 +4,7 @@ Acceptance test tasks
 from paver.easy import cmdopts, needs
 from pavelib.utils.test.suites import AcceptanceTestSuite
 from pavelib.utils.passthrough_opts import PassthroughTask
+from pavelib.utils.timer import timed
 from optparse import make_option
 
 try:
@@ -29,6 +30,7 @@ __test__ = False  # do not collect
     ('extra_args=', 'e', 'deprecated, pass extra options directly in the paver commandline'),
 ])
 @PassthroughTask
+@timed
 def test_acceptance(options, passthrough_options):
     """
     Run the acceptance tests for either lms or cms

pavelib/assets.py

@@ -17,6 +17,7 @@ from watchdog.events import PatternMatchingEventHandler
 
 from .utils.envs import Env
 from .utils.cmd import cmd, django_cmd
+from .utils.timer import timed
 
 from openedx.core.djangoapps.theming.paver_helpers import get_theme_paths
 
@@ -387,6 +388,7 @@ def coffeescript_files():
 
 @task
 @no_help
+@timed
 def compile_coffeescript(*files):
     """
     Compile CoffeeScript to JavaScript.
@@ -407,6 +409,7 @@ def compile_coffeescript(*files):
     ('debug', 'd', 'Debug mode'),
     ('force', '', 'Force full compilation'),
 ])
+@timed
 def compile_sass(options):
     """
     Compile Sass to CSS. If command is called without any arguments, it will
@@ -694,6 +697,7 @@ def execute_compile_sass(args):
     ('theme-dirs=', '-td', 'The themes dir containing all themes (defaults to None)'),
     ('themes=', '-t', 'The themes to add sass watchers for (defaults to None)'),
 ])
+@timed
 def watch_assets(options):
     """
     Watch for changes to asset files, and regenerate js/css
@@ -742,6 +746,7 @@ def watch_assets(options):
     'pavelib.prereqs.install_node_prereqs',
 )
 @consume_args
+@timed
 def update_assets(args):
     """
     Compile CoffeeScript and Sass, then collect static assets.

pavelib/bok_choy.py

@@ -4,9 +4,16 @@ http://bok-choy.readthedocs.org/en/latest/
 """
 from paver.easy import task, needs, cmdopts, sh
 from pavelib.utils.test.suites.bokchoy_suite import BokChoyTestSuite, Pa11yCrawler
+from pavelib.utils.test.bokchoy_options import (
+    BOKCHOY_OPTS,
+    PA11Y_HTML,
+    PA11Y_COURSE_KEY,
+    PA11Y_FETCH_COURSE,
+)
 from pavelib.utils.envs import Env
 from pavelib.utils.test.utils import check_firefox_version
 from pavelib.utils.passthrough_opts import PassthroughTask
+from pavelib.utils.timer import timed
 from optparse import make_option
 import os
 
@@ -17,75 +24,11 @@ except ImportError:
 
 __test__ = False  # do not collect
 
-BOKCHOY_OPTS = [
-    ('test-spec=', 't', 'Specific test to run'),
-    ('fasttest', 'a', 'Skip some setup'),
-    ('skip-clean', 'C', 'Skip cleaning repository before running tests'),
-    ('serversonly', 'r', 'Prepare suite and leave servers running'),
-    ('testsonly', 'o', 'Assume servers are running and execute tests only'),
-    ('default-store=', 's', 'Default modulestore'),
-    ('test-dir=', 'd', 'Directory for finding tests (relative to common/test/acceptance)'),
-    ('imports-dir=', 'i', 'Directory containing (un-archived) courses to be imported'),
-    ('num-processes=', 'n', 'Number of test threads (for multiprocessing)'),
-    ('verify-xss', 'x', 'Run XSS vulnerability tests'),
-    make_option("--verbose", action="store_const", const=2, dest="verbosity"),
-    make_option("-q", "--quiet", action="store_const", const=0, dest="verbosity"),
-    make_option("-v", "--verbosity", action="count", dest="verbosity"),
-    make_option("--skip-firefox-version-validation", action='store_false', dest="validate_firefox_version"),
-    make_option("--save-screenshots", action='store_true', dest="save_screenshots"),
-    ('default_store=', None, 'deprecated in favor of default-store'),
-    ('extra_args=', 'e', 'deprecated, pass extra options directly in the paver commandline'),
-    ('imports_dir=', None, 'deprecated in favor of imports-dir'),
-    ('num_processes=', None, 'deprecated in favor of num-processes'),
-    ('skip_clean', None, 'deprecated in favor of skip-clean'),
-    ('test_dir=', None, 'deprecated in favor of test-dir'),
-    ('test_spec=', None, 'Specific test to run'),
-    ('verify_xss', None, 'deprecated in favor of verify-xss'),
-    make_option(
-        "--skip_firefox_version_validation",
-        action='store_false',
-        dest="validate_firefox_version",
-        help="deprecated in favor of --skip-firefox-version-validation"
-    ),
-    make_option(
-        "--save_screenshots",
-        action='store_true',
-        dest="save_screenshots",
-        help="deprecated in favor of save-screenshots"
-    ),
-]
-
-
-def parse_bokchoy_opts(options, passthrough_options=None):
-    """
-    Parses bok choy options.
-
-    Returns: dict of options.
-    """
-    if passthrough_options is None:
-        passthrough_options = []
-
-    return {
-        'test_spec': getattr(options, 'test_spec', None),
-        'fasttest': getattr(options, 'fasttest', False),
-        'num_processes': int(getattr(options, 'num_processes', 1)),
-        'verify_xss': getattr(options, 'verify_xss', os.environ.get('VERIFY_XSS', False)),
-        'serversonly': getattr(options, 'serversonly', False),
-        'testsonly': getattr(options, 'testsonly', False),
-        'default_store': getattr(options, 'default_store', os.environ.get('DEFAULT_STORE', 'split')),
-        'verbosity': getattr(options, 'verbosity', 2),
-        'extra_args': getattr(options, 'extra_args', ''),
-        'pdb': getattr(options, 'pdb', False),
-        'test_dir': getattr(options, 'test_dir', 'tests'),
-        'imports_dir': getattr(options, 'imports_dir', None),
-        'save_screenshots': getattr(options, 'save_screenshots', False),
-        'passthrough_options': passthrough_options
-    }
-
 
 @needs('pavelib.prereqs.install_prereqs')
 @cmdopts(BOKCHOY_OPTS)
 @PassthroughTask
+@timed
 def test_bokchoy(options, passthrough_options):
     """
     Run acceptance tests that use the bok-choy framework.
@@ -109,13 +52,13 @@ def test_bokchoy(options, passthrough_options):
     if validate_firefox:
         check_firefox_version()
 
-    opts = parse_bokchoy_opts(options, passthrough_options)
-    run_bokchoy(**opts)
+    run_bokchoy(options.test_bokchoy, passthrough_options)
 
 
 @needs('pavelib.prereqs.install_prereqs')
 @cmdopts(BOKCHOY_OPTS)
 @PassthroughTask
+@timed
 def test_a11y(options, passthrough_options):
     """
     Run accessibility tests that use the bok-choy framework.
@@ -132,38 +75,36 @@ def test_a11y(options, passthrough_options):
     It can also be left blank to run all tests in the suite that are tagged
     with `@attr("a11y")`.
     """
-    opts = parse_bokchoy_opts(options, passthrough_options)
-    opts['report_dir'] = Env.BOK_CHOY_A11Y_REPORT_DIR
-    opts['coveragerc'] = Env.BOK_CHOY_A11Y_COVERAGERC
-    opts['extra_args'] = opts['extra_args'] + ' -a "a11y" '
-    run_bokchoy(**opts)
+    # Modify the options object directly, so that any subsequently called tasks
+    # that share with this task get the modified options
+    options.test_a11y.report_dir = Env.BOK_CHOY_A11Y_REPORT_DIR
+    options.test_a11y.coveragerc = Env.BOK_CHOY_A11Y_COVERAGERC
+    options.test_a11y.extra_args = options.get('extra_args', '') + ' -a "a11y" '
+    run_bokchoy(options.test_a11y, passthrough_options)
 
 
 @needs('pavelib.prereqs.install_prereqs')
 @cmdopts(BOKCHOY_OPTS)
 @PassthroughTask
+@timed
 def perf_report_bokchoy(options, passthrough_options):
     """
     Generates a har file for with page performance info.
     """
-    opts = parse_bokchoy_opts(options, passthrough_options)
-    opts['test_dir'] = 'performance'
+    # Modify the options object directly, so that any subsequently called tasks
+    # that share with this task get the modified options
+    options.perf_report_bokchoy.test_dir = 'performance'
 
-    run_bokchoy(**opts)
+    run_bokchoy(options.perf_report_bokchoy, passthrough_options)
 
 
-@needs('pavelib.prereqs.install_prereqs')
-@cmdopts(BOKCHOY_OPTS + [
-    ('with-html', 'w', 'Include html reports'),
-    make_option('--course-key', help='Course key for test course'),
-    make_option(
-        "--fetch-course",
-        action="store_true",
-        dest="should_fetch_course",
-        help='Course key for test course',
-    ),
-])
+@needs('pavelib.prereqs.install_prereqs', 'get_test_course')
+@cmdopts(
+    BOKCHOY_OPTS + [PA11Y_HTML, PA11Y_COURSE_KEY, PA11Y_FETCH_COURSE],
+    share_with=['get_test_course', 'prepare_bokchoy_run', 'load_courses']
+)
 @PassthroughTask
+@timed
 def pa11ycrawler(options, passthrough_options):
     """
     Runs pa11ycrawler against the demo-test-course to generates accessibility
@@ -173,23 +114,28 @@ def pa11ycrawler(options, passthrough_options):
     flag to get an environment running. The setup for this is the same as
     for bok-choy tests, only test course is imported as well.
     """
-    opts = parse_bokchoy_opts(options, passthrough_options)
-    opts['report_dir'] = Env.PA11YCRAWLER_REPORT_DIR
-    opts['coveragerc'] = Env.PA11YCRAWLER_COVERAGERC
-    opts['should_fetch_course'] = getattr(options, 'should_fetch_course', not opts['fasttest'])
-    opts['course_key'] = getattr(options, 'course-key', "course-v1:edX+Test101+course")
-    test_suite = Pa11yCrawler('a11y_crawler', **opts)
+    # Modify the options object directly, so that any subsequently called tasks
+    # that share with this task get the modified options
+    options.pa11ycrawler.report_dir = Env.PA11YCRAWLER_REPORT_DIR
+    options.pa11ycrawler.coveragerc = Env.PA11YCRAWLER_COVERAGERC
+    options.pa11ycrawler.should_fetch_course = getattr(
+        options,
+        'should_fetch_course',
+        not options.get('fasttest')
+    )
+    options.pa11ycrawler.course_key = getattr(options, 'course-key', "course-v1:edX+Test101+course")
+    test_suite = Pa11yCrawler('a11y_crawler', passthrough_options=passthrough_options, **options.pa11ycrawler)
     test_suite.run()
 
     if getattr(options, 'with_html', False):
         test_suite.generate_html_reports()
 
 
-def run_bokchoy(**opts):
+def run_bokchoy(options, passthrough_options):
     """
     Runs BokChoyTestSuite with the given options.
     """
-    test_suite = BokChoyTestSuite('bok-choy', **opts)
+    test_suite = BokChoyTestSuite('bok-choy', passthrough_options=passthrough_options, **options)
     msg = colorize(
         'green',
         'Running tests using {default_store} modulestore.'.format(
@@ -220,6 +166,7 @@ def parse_coverage(report_dir, coveragerc):
 
 
 @task
+@timed
 def bokchoy_coverage():
     """
     Generate coverage reports for bok-choy tests
@@ -231,6 +178,7 @@ def bokchoy_coverage():
 
 
 @task
+@timed
 def a11y_coverage():
     """
     Generate coverage reports for a11y tests. Note that this coverage report
@@ -246,6 +194,7 @@ def a11y_coverage():
 
 
 @task
+@timed
 def pa11ycrawler_coverage():
     """
     Generate coverage reports for bok-choy tests

pavelib/docs.py

@@ -7,6 +7,8 @@ import sys
 
 from paver.easy import cmdopts, needs, sh, task
 
+from .utils.timer import timed
+
 
 DOC_PATHS = {
     "dev": "docs/en_us/developers",
@@ -64,6 +66,7 @@ def doc_path(options, allow_default=True):
     ("type=", "t", "Type of docs to compile"),
     ("verbose", "v", "Display verbose output"),
 ])
+@timed
 def build_docs(options):
     """
     Invoke sphinx 'make build' to generate docs.

pavelib/i18n.py

@@ -10,6 +10,7 @@ from path import Path as path
 from paver.easy import task, cmdopts, needs, sh
 
 from .utils.cmd import django_cmd
+from .utils.timer import timed
 
 try:
     from pygments.console import colorize
@@ -28,6 +29,7 @@ DEFAULT_SETTINGS = 'devstack'
 @cmdopts([
     ("verbose", "v", "Sets 'verbose' to True"),
 ])
+@timed
 def i18n_extract(options):
     """
     Extract localizable strings from sources
@@ -42,6 +44,7 @@ def i18n_extract(options):
 
 
 @task
+@timed
 def i18n_fastgenerate():
     """
     Compile localizable strings from sources without re-extracting strings first.
@@ -51,6 +54,7 @@ def i18n_fastgenerate():
 
 @task
 @needs("pavelib.i18n.i18n_extract")
+@timed
 def i18n_generate():
     """
     Compile localizable strings from sources, extracting strings first.
@@ -60,6 +64,7 @@ def i18n_generate():
 
 @task
 @needs("pavelib.i18n.i18n_extract")
+@timed
 def i18n_generate_strict():
     """
     Compile localizable strings from sources, extracting strings first.
@@ -70,6 +75,7 @@ def i18n_generate_strict():
 
 @task
 @needs("pavelib.i18n.i18n_extract")
+@timed
 def i18n_dummy():
     """
     Simulate international translation by generating dummy strings
@@ -85,6 +91,7 @@ def i18n_dummy():
 
 
 @task
+@timed
 def i18n_validate_gettext():
     """
     Make sure GNU gettext utilities are available
@@ -107,6 +114,7 @@ def i18n_validate_gettext():
 
 
 @task
+@timed
 def i18n_validate_transifex_config():
     """
     Make sure config file with username/password exists
@@ -130,6 +138,7 @@ def i18n_validate_transifex_config():
 
 @task
 @needs("pavelib.i18n.i18n_validate_transifex_config")
+@timed
 def i18n_transifex_push():
     """
     Push source strings to Transifex for translation
@@ -139,6 +148,7 @@ def i18n_transifex_push():
 
 @task
 @needs("pavelib.i18n.i18n_validate_transifex_config")
+@timed
 def i18n_transifex_pull():
     """
     Pull translated strings from Transifex
@@ -147,6 +157,7 @@ def i18n_transifex_pull():
 
 
 @task
+@timed
 def i18n_rtl():
     """
     Pull all RTL translations (reviewed AND unreviewed) from Transifex
@@ -164,6 +175,7 @@ def i18n_rtl():
 
 
 @task
+@timed
 def i18n_ltr():
     """
     Pull all LTR translations (reviewed AND unreviewed) from Transifex
@@ -188,6 +200,7 @@ def i18n_ltr():
     "pavelib.i18n.i18n_dummy",
     "pavelib.i18n.i18n_generate_strict",
 )
+@timed
 def i18n_robot_pull():
     """
     Pull source strings, generate po and mo files, and validate
@@ -215,6 +228,7 @@ def i18n_robot_pull():
 
 
 @task
+@timed
 def i18n_clean():
     """
     Clean the i18n directory of artifacts
@@ -227,6 +241,7 @@ def i18n_clean():
     "pavelib.i18n.i18n_extract",
     "pavelib.i18n.i18n_transifex_push",
 )
+@timed
 def i18n_robot_push():
     """
     Extract new strings, and push to transifex
@@ -239,6 +254,7 @@ def i18n_robot_push():
     "pavelib.i18n.i18n_validate_transifex_config",
     "pavelib.i18n.i18n_generate",
 )
+@timed
 def i18n_release_push():
     """
     Push release-specific resources to Transifex.
@@ -251,6 +267,7 @@ def i18n_release_push():
 @needs(
     "pavelib.i18n.i18n_validate_transifex_config",
 )
+@timed
 def i18n_release_pull():
     """
     Pull release-specific translations from Transifex.

pavelib/js_test.py

@@ -5,6 +5,7 @@ import sys
 from paver.easy import task, cmdopts, needs
 from pavelib.utils.test.suites import JsTestSuite
 from pavelib.utils.envs import Env
+from pavelib.utils.timer import timed
 
 __test__ = False  # do not collect
 
@@ -22,6 +23,7 @@ __test__ = False  # do not collect
     ('skip-clean', 'C', 'skip cleaning repository before running tests'),
     ('skip_clean', None, 'deprecated in favor of skip-clean'),
 ], share_with=["pavelib.utils.tests.utils.clean_reports_dir"])
+@timed
 def test_js(options):
     """
     Run the JavaScript tests
@@ -58,6 +60,7 @@ def test_js(options):
     ("suite=", "s", "Test suite to run"),
     ("coverage", "c", "Run test under coverage"),
 ])
+@timed
 def test_js_run(options):
     """
     Run the JavaScript tests and print results to the console
@@ -71,6 +74,7 @@ def test_js_run(options):
     ("suite=", "s", "Test suite to run"),
     ("port=", "p", "Port to run test server on"),
 ])
+@timed
 def test_js_dev(options):
     """
     Run the JavaScript tests in your default browsers

pavelib/paver_tests/test_paver_bok_choy_cmds.py

@@ -5,10 +5,12 @@ Run just this test with: paver test_lib -t pavelib/paver_tests/test_paver_bok_ch
 import os
 import unittest
 
+import ddt
 from mock import patch, call
 from test.test_support import EnvironmentVarGuard
-from paver.easy import BuildFailure
+from paver.easy import BuildFailure, call_task, environment
 from pavelib.utils.test.suites import BokChoyTestSuite, Pa11yCrawler
+from pavelib.utils.test.suites.bokchoy_suite import DEMO_COURSE_TAR_GZ, DEMO_COURSE_IMPORT_DIR
 
 REPO_DIR = os.getcwd()
 
@@ -173,6 +175,7 @@ class TestPaverBokChoyCmd(unittest.TestCase):
             suite.verbosity_processes_command
 
 
+@ddt.ddt
 class TestPaverPa11yCrawlerCmd(unittest.TestCase):
 
     """
@@ -190,6 +193,9 @@ class TestPaverPa11yCrawlerCmd(unittest.TestCase):
         # Cleanup mocks
         self.addCleanup(mock_sh.stop)
 
+        # reset the options for all tasks
+        environment.options.clear()
+
     def _expected_command(self, report_dir, start_urls):
         """
         Returns the expected command to run pa11ycrawler.
@@ -213,15 +219,31 @@ class TestPaverPa11yCrawlerCmd(unittest.TestCase):
             self._expected_command(suite.pa11y_report_dir, suite.start_urls)
         )
 
-    def test_get_test_course(self):
-        suite = Pa11yCrawler('')
-        suite.get_test_course()
-        self._mock_sh.assert_has_calls([
-            call(
-                'wget {targz} -O {dir}demo_course.tar.gz'.format(targz=suite.tar_gz_file, dir=suite.imports_dir)),
-            call(
-                'tar zxf {dir}demo_course.tar.gz -C {dir}'.format(dir=suite.imports_dir)),
-        ])
+    @ddt.data(
+        (True, True, None),
+        (True, False, None),
+        (False, True, DEMO_COURSE_IMPORT_DIR),
+        (False, False, None),
+    )
+    @ddt.unpack
+    def test_get_test_course(self, import_dir_set, should_fetch_course_set, downloaded_to):
+        options = {}
+        if import_dir_set:
+            options['imports_dir'] = 'some_import_dir'
+        if should_fetch_course_set:
+            options['should_fetch_course'] = True
+
+        call_task('pavelib.utils.test.suites.bokchoy_suite.get_test_course', options=options)
+
+        if downloaded_to is None:
+            self._mock_sh.assert_has_calls([])
+        else:
+            self._mock_sh.assert_has_calls([
+                call(
+                    'wget {targz} -O {dir}demo_course.tar.gz'.format(targz=DEMO_COURSE_TAR_GZ, dir=downloaded_to)),
+                call(
+                    'tar zxf {dir}demo_course.tar.gz -C {dir}'.format(dir=downloaded_to)),
+            ])
 
     def test_generate_html_reports(self):
         suite = Pa11yCrawler('')

pavelib/paver_tests/test_timer.py

+"""
+Tests of the pavelib.utils.timer module.
+"""
+
+from datetime import datetime, timedelta
+from mock import patch, MagicMock
+from unittest import TestCase
+
+from pavelib.utils import timer
+
+
+@timer.timed
+def identity(*args, **kwargs):
+    """
+    An identity function used as a default task to test the timing of.
+    """
+    return args, kwargs
+
+
+MOCK_OPEN = MagicMock(spec=open)
+
+
+@patch.dict('pavelib.utils.timer.__builtins__', open=MOCK_OPEN)
+class TimedDecoratorTests(TestCase):
+    """
+    Tests of the pavelib.utils.timer:timed decorator.
+    """
+    def setUp(self):
+        super(TimedDecoratorTests, self).setUp()
+
+        patch_dumps = patch.object(timer.json, 'dump', autospec=True)
+        self.mock_dump = patch_dumps.start()
+        self.addCleanup(patch_dumps.stop)
+
+        patch_makedirs = patch.object(timer.os, 'makedirs', autospec=True)
+        self.mock_makedirs = patch_makedirs.start()
+        self.addCleanup(patch_makedirs.stop)
+
+        patch_datetime = patch.object(timer, 'datetime', autospec=True)
+        self.mock_datetime = patch_datetime.start()
+        self.addCleanup(patch_datetime.stop)
+
+        patch_exists = patch.object(timer, 'exists', autospec=True)
+        self.mock_exists = patch_exists.start()
+        self.addCleanup(patch_exists.stop)
+
+        MOCK_OPEN.reset_mock()
+
+    def get_log_messages(self, task=identity, args=None, kwargs=None, raises=None):
+        """
+        Return all timing messages recorded during the execution of ``task``.
+        """
+        if args is None:
+            args = []
+        if kwargs is None:
+            kwargs = {}
+
+        if raises is None:
+            task(*args, **kwargs)
+        else:
+            self.assertRaises(raises, task, *args, **kwargs)
+
+        return [
+            call[0][0]  # log_message
+            for call in self.mock_dump.call_args_list
+        ]
+
+    @patch.object(timer, 'PAVER_TIMER_LOG', '/tmp/some-log')
+    def test_times(self):
+        start = datetime(2016, 7, 20, 10, 56, 19)
+        end = start + timedelta(seconds=35.6)
+
+        self.mock_datetime.utcnow.side_effect = [start, end]
+
+        messages = self.get_log_messages()
+        self.assertEquals(len(messages), 1)
+
+        # I'm not using assertDictContainsSubset because it is
+        # removed in python 3.2 (because the arguments were backwards)
+        # and it wasn't ever replaced by anything *headdesk*
+        self.assertIn('duration', messages[0])
+        self.assertEquals(35.6, messages[0]['duration'])
+
+        self.assertIn('started_at', messages[0])
+        self.assertEquals(start.isoformat(' '), messages[0]['started_at'])
+
+        self.assertIn('ended_at', messages[0])
+        self.assertEquals(end.isoformat(' '), messages[0]['ended_at'])
+
+    @patch.object(timer, 'PAVER_TIMER_LOG', None)
+    def test_no_logs(self):
+        messages = self.get_log_messages()
+        self.assertEquals(len(messages), 0)
+
+    @patch.object(timer, 'PAVER_TIMER_LOG', '/tmp/some-log')
+    def test_arguments(self):
+        messages = self.get_log_messages(args=(1, 'foo'), kwargs=dict(bar='baz'))
+        self.assertEquals(len(messages), 1)
+
+        # I'm not using assertDictContainsSubset because it is
+        # removed in python 3.2 (because the arguments were backwards)
+        # and it wasn't ever replaced by anything *headdesk*
+        self.assertIn('args', messages[0])
+        self.assertEquals([repr(1), repr('foo')], messages[0]['args'])
+        self.assertIn('kwargs', messages[0])
+        self.assertEquals({'bar': repr('baz')}, messages[0]['kwargs'])
+
+    @patch.object(timer, 'PAVER_TIMER_LOG', '/tmp/some-log')
+    def test_task_name(self):
+        messages = self.get_log_messages()
+        self.assertEquals(len(messages), 1)
+
+        # I'm not using assertDictContainsSubset because it is
+        # removed in python 3.2 (because the arguments were backwards)
+        # and it wasn't ever replaced by anything *headdesk*
+        self.assertIn('task', messages[0])
+        self.assertEquals('pavelib.paver_tests.test_timer.identity', messages[0]['task'])
+
+    @patch.object(timer, 'PAVER_TIMER_LOG', '/tmp/some-log')
+    def test_exceptions(self):
+
+        @timer.timed
+        def raises():
+            """
+            A task used for testing exception handling of the timed decorator.
+            """
+            raise Exception('The Message!')
+
+        messages = self.get_log_messages(task=raises, raises=Exception)
+        self.assertEquals(len(messages), 1)
+
+        # I'm not using assertDictContainsSubset because it is
+        # removed in python 3.2 (because the arguments were backwards)
+        # and it wasn't ever replaced by anything *headdesk*
+        self.assertIn('exception', messages[0])
+        self.assertEquals("Exception: The Message!", messages[0]['exception'])
+
+    @patch.object(timer, 'PAVER_TIMER_LOG', '/tmp/some-log-%Y-%m-%d-%H-%M-%S.log')
+    def test_date_formatting(self):
+        start = datetime(2016, 7, 20, 10, 56, 19)
+        end = start + timedelta(seconds=35.6)
+
+        self.mock_datetime.utcnow.side_effect = [start, end]
+
+        messages = self.get_log_messages()
+        self.assertEquals(len(messages), 1)
+
+        MOCK_OPEN.assert_called_once_with('/tmp/some-log-2016-07-20-10-56-19.log', 'a')
+
+    @patch.object(timer, 'PAVER_TIMER_LOG', '/tmp/some-log')
+    def test_nested_tasks(self):
+
+        @timer.timed
+        def parent():
+            """
+            A timed task that calls another task
+            """
+            identity()
+
+        parent_start = datetime(2016, 7, 20, 10, 56, 19)
+        parent_end = parent_start + timedelta(seconds=60)
+        child_start = parent_start + timedelta(seconds=10)
+        child_end = parent_end - timedelta(seconds=10)
+
+        self.mock_datetime.utcnow.side_effect = [parent_start, child_start, child_end, parent_end]
+
+        messages = self.get_log_messages(task=parent)
+        self.assertEquals(len(messages), 2)
+
+        # Child messages first
+        self.assertIn('duration', messages[0])
+        self.assertEquals(40, messages[0]['duration'])
+
+        self.assertIn('started_at', messages[0])
+        self.assertEquals(child_start.isoformat(' '), messages[0]['started_at'])
+
+        self.assertIn('ended_at', messages[0])
+        self.assertEquals(child_end.isoformat(' '), messages[0]['ended_at'])
+
+        # Parent messages after
+        self.assertIn('duration', messages[1])
+        self.assertEquals(60, messages[1]['duration'])
+
+        self.assertIn('started_at', messages[1])
+        self.assertEquals(parent_start.isoformat(' '), messages[1]['started_at'])
+
+        self.assertIn('ended_at', messages[1])
+        self.assertEquals(parent_end.isoformat(' '), messages[1]['ended_at'])

pavelib/prereqs.py

@@ -11,6 +11,7 @@ import sys
 from paver.easy import sh, task
 
 from .utils.envs import Env
+from .utils.timer import timed
 
 
 PREREQS_STATE_DIR = os.getenv('PREREQ_CACHE_DIR', Env.REPO_ROOT / '.prereqs_cache')
@@ -145,6 +146,7 @@ def python_prereqs_installation():
 
 
 @task
+@timed
 def install_node_prereqs():
     """
     Installs Node prerequisites
@@ -168,6 +170,7 @@ PACKAGES_TO_UNINSTALL = [
 
 
 @task
+@timed
 def uninstall_python_packages():
     """
     Uninstall Python packages that need explicit uninstallation.
@@ -235,6 +238,7 @@ def package_in_frozen(package_name, frozen_output):
 
 
 @task
+@timed
 def install_python_prereqs():
     """
     Installs Python prerequisites.
@@ -268,6 +272,7 @@ def install_python_prereqs():
 
 
 @task
+@timed
 def install_prereqs():
     """
     Installs Node and Python prerequisites

pavelib/quality.py

@@ -9,6 +9,7 @@ import re
 from openedx.core.djangolib.markup import HTML
 
 from .utils.envs import Env
+from .utils.timer import timed
 
 ALL_SYSTEMS = 'lms,cms,common,openedx,pavelib'
 
@@ -38,6 +39,7 @@ def top_python_dirs(dirname):
 @cmdopts([
     ("system=", "s", "System to act on"),
 ])
+@timed
 def find_fixme(options):
     """
     Run pylint on system code, only looking for fixme items.
@@ -82,6 +84,7 @@ def find_fixme(options):
     ("errors", "e", "Check for errors only"),
     ("limit=", "l", "limit for number of acceptable violations"),
 ])
+@timed
 def run_pylint(options):
     """
     Run pylint on system code. When violations limit is passed in,
@@ -197,6 +200,7 @@ def _pep8_violations(report_file):
 @cmdopts([
     ("system=", "s", "System to act on"),
 ])
+@timed
 def run_pep8(options):  # pylint: disable=unused-argument
     """
     Run pep8 on system code.
@@ -224,6 +228,7 @@ def run_pep8(options):  # pylint: disable=unused-argument
 
 @task
 @needs('pavelib.prereqs.install_python_prereqs')
+@timed
 def run_complexity():
     """
     Uses radon to examine cyclomatic complexity.
@@ -262,6 +267,7 @@ def run_complexity():
 @cmdopts([
     ("limit=", "l", "limit for number of acceptable violations"),
 ])
+@timed
 def run_eslint(options):
     """
     Runs eslint on static asset directories.
@@ -306,6 +312,7 @@ def run_eslint(options):
 @cmdopts([
     ("thresholds=", "t", "json containing limit for number of acceptable violations per rule"),
 ])
+@timed
 def run_safelint(options):
     """
     Runs safe_template_linter.py on the codebase
@@ -407,6 +414,7 @@ def run_safelint(options):
 
 @task
 @needs('pavelib.prereqs.install_python_prereqs')
+@timed
 def run_safecommit_report():
     """
     Runs safe-commit-linter.sh on the current branch.
@@ -584,6 +592,7 @@ def _get_safecommit_count(filename):
     ("compare-branch=", "b", "Branch to compare against, defaults to origin/master"),
     ("percentage=", "p", "fail if diff-quality is below this percentage"),
 ])
+@timed
 def run_quality(options):
     """
     Build the html diff quality reports, and print the reports to the console.

pavelib/servers.py

@@ -10,6 +10,7 @@ from paver.easy import call_task, cmdopts, consume_args, needs, sh, task
 from .assets import collect_assets
 from .utils.cmd import django_cmd
 from .utils.process import run_process, run_multi_processes
+from .utils.timer import timed
 
 
 DEFAULT_PORT = {"lms": 8000, "studio": 8001}
@@ -244,6 +245,7 @@ def run_all_servers(options):
     ("settings=", "s", "Django settings"),
     ("fake-initial", None, "Fake the initial migrations"),
 ])
+@timed
 def update_db(options):
     """
     Migrates the lms and cms across all databases
@@ -261,6 +263,7 @@ def update_db(options):
 @task
 @needs('pavelib.prereqs.install_prereqs')
 @consume_args
+@timed
 def check_settings(args):
     """
     Checks settings files.

pavelib/tests.py

@@ -7,6 +7,7 @@ import sys
 from paver.easy import sh, task, cmdopts, needs
 from pavelib.utils.test import suites
 from pavelib.utils.envs import Env
+from pavelib.utils.timer import timed
 from pavelib.utils.passthrough_opts import PassthroughTask
 from optparse import make_option
 
@@ -55,6 +56,7 @@ __test__ = False  # do not collect
     ('skip_clean', None, 'deprecated in favor of skip-clean'),
 ], share_with=['pavelib.utils.test.utils.clean_reports_dir'])
 @PassthroughTask
+@timed
 def test_system(options, passthrough_options):
     """
     Run tests on our djangoapps for lms and cms
@@ -120,6 +122,7 @@ def test_system(options, passthrough_options):
     ("test_id=", None, "deprecated in favor of test-id"),
 ], share_with=['pavelib.utils.test.utils.clean_reports_dir'])
 @PassthroughTask
+@timed
 def test_lib(options, passthrough_options):
     """
     Run tests for common/lib/ and pavelib/ (paver-tests)
@@ -184,6 +187,7 @@ def test_lib(options, passthrough_options):
     ("fail_fast", None, "deprecated in favor of fail-fast"),
 ])
 @PassthroughTask
+@timed
 def test_python(options, passthrough_options):
     """
     Run all python tests
@@ -216,6 +220,7 @@ def test_python(options, passthrough_options):
     ),
 ])
 @PassthroughTask
+@timed
 def test(options, passthrough_options):
     """
     Run all tests
@@ -239,7 +244,8 @@ def test(options, passthrough_options):
     ("compare-branch=", "b", "Branch to compare against, defaults to origin/master"),
     ("compare_branch=", None, "deprecated in favor of compare-branch"),
 ])
-def coverage(options):
+@timed
+def coverage():
     """
     Build the html, xml, and diff coverage reports
     """
@@ -276,6 +282,7 @@ def coverage(options):
     ("compare-branch=", "b", "Branch to compare against, defaults to origin/master"),
     ("compare_branch=", None, "deprecated in favor of compare-branch"),
 ], share_with=['coverage'])
+@timed
 def diff_coverage(options):
     """
     Build the diff coverage reports

pavelib/utils/test/bokchoy_options.py

+"""
+Definitions of all options used by the various bok_choy tasks.
+"""
+
+from optparse import make_option
+import os
+
+from pavelib.utils.envs import Env
+
+
+BOKCHOY_IMPORTS_DIR = ('imports-dir=', 'i', 'Directory containing (un-archived) courses to be imported')
+BOKCHOY_IMPORTS_DIR_DEPR = ('imports_dir=', None, 'deprecated in favor of imports-dir')
+BOKCHOY_DEFAULT_STORE = make_option(
+    "-s", "--default-store",
+    default=os.environ.get('DEFAULT_STORE', 'split'),
+    help='Default modulestore'
+)
+BOKCHOY_DEFAULT_STORE_DEPR = make_option(
+    "--default_store",
+    default=os.environ.get('DEFAULT_STORE', 'split'),
+    help='deprecated in favor of default-store'
+)
+BOKCHOY_FASTTEST = make_option('-a', '--fasttest', action='store_true', help='Skip some setup')
+BOKCHOY_COVERAGERC = make_option('--coveragerc', help='coveragerc file to use during this test')
+
+BOKCHOY_OPTS = [
+    ('test-spec=', 't', 'Specific test to run'),
+    BOKCHOY_FASTTEST,
+    ('skip-clean', 'C', 'Skip cleaning repository before running tests'),
+    make_option('-r', '--serversonly', action='store_true', help='Prepare suite and leave servers running'),
+    make_option('-o', '--testsonly', action='store_true', help='Assume servers are running and execute tests only'),
+    BOKCHOY_DEFAULT_STORE,
+    make_option(
+        '-d', '--test-dir',
+        default='tests',
+        help='Directory for finding tests (relative to common/test/acceptance)'
+    ),
+    BOKCHOY_IMPORTS_DIR,
+    make_option('-n', '--num-processes', type='int', help='Number of test threads (for multiprocessing)'),
+    make_option(
+        '-x', '--verify-xss',
+        action='store_true',
+        default=os.environ.get('VERIFY_XSS', False),
+        help='Run XSS vulnerability tests'
+    ),
+    make_option("--verbose", action="store_const", const=2, dest="verbosity"),
+    make_option("-q", "--quiet", action="store_const", const=0, dest="verbosity"),
+    make_option("-v", "--verbosity", action="count", dest="verbosity"),
+    make_option("--skip-firefox-version-validation", action='store_false', dest="validate_firefox_version"),
+    make_option("--save-screenshots", action='store_true', dest="save_screenshots"),
+    make_option("--report-dir", default=Env.BOK_CHOY_REPORT_DIR, help="Directory to store reports in"),
+
+    BOKCHOY_DEFAULT_STORE_DEPR,
+    make_option(
+        '-e', '--extra_args',
+        default='',
+        help='deprecated, pass extra options directly in the paver commandline'
+    ),
+    BOKCHOY_IMPORTS_DIR_DEPR,
+    make_option('--num_processes', type='int', help='deprecated in favor of num-processes'),
+    ('skip_clean', None, 'deprecated in favor of skip-clean'),
+    make_option('--test_dir', default='tests', help='deprecated in favor of test-dir'),
+    ('test_spec=', None, 'Specific test to run'),
+    make_option(
+        '--verify_xss',
+        action='store_true',
+        default=os.environ.get('VERIFY_XSS', False),
+        help='deprecated in favor of verify-xss'
+    ),
+    make_option(
+        "--skip_firefox_version_validation",
+        action='store_false',
+        dest="validate_firefox_version",
+        help="deprecated in favor of --skip-firefox-version-validation"
+    ),
+    make_option(
+        "--save_screenshots",
+        action='store_true',
+        dest="save_screenshots",
+        help="deprecated in favor of save-screenshots"
+    ),
+]
+
+PA11Y_HTML = ('with-html', 'w', 'Include html reports')
+PA11Y_COURSE_KEY = make_option('--course-key', help='Course key for test course')
+PA11Y_FETCH_COURSE = make_option(
+    "--fetch-course",
+    action="store_true",
+    dest="should_fetch_course",
+    help='Course key for test course',
+)

pavelib/utils/test/bokchoy_utils.py

@@ -6,9 +6,14 @@ import os
 import time
 import httplib
 import subprocess
-from paver.easy import sh
+from paver import tasks
+from paver.easy import sh, task, cmdopts, needs
 from pavelib.utils.envs import Env
 from pavelib.utils.process import run_background_process
+from pavelib.utils.test.bokchoy_options import (
+    BOKCHOY_COVERAGERC, BOKCHOY_DEFAULT_STORE, BOKCHOY_DEFAULT_STORE_DEPR
+)
+from pavelib.utils.timer import timed
 
 try:
     from pygments.console import colorize
@@ -18,11 +23,14 @@ except ImportError:
 __test__ = False  # do not collect
 
 
-def start_servers(default_store, coveragerc=None):
+@task
+@cmdopts([BOKCHOY_COVERAGERC, BOKCHOY_DEFAULT_STORE, BOKCHOY_DEFAULT_STORE_DEPR])
+@timed
+def start_servers(options):
     """
     Start the servers we will run tests on, returns PIDs for servers.
     """
-    coveragerc = coveragerc or Env.BOK_CHOY_COVERAGERC
+    coveragerc = options.get('coveragerc', Env.BOK_CHOY_COVERAGERC)
 
     def start_server(cmd, logfile, cwd=None):
         """
@@ -38,7 +46,7 @@ def start_servers(default_store, coveragerc=None):
             "coverage run --rcfile={coveragerc} -m "
             "manage {service} --settings bok_choy runserver "
             "{address} --traceback --noreload".format(
-                default_store=default_store,
+                default_store=options.default_store,
                 coveragerc=coveragerc,
                 service=service,
                 address=address,
@@ -69,6 +77,9 @@ def wait_for_server(server, port):
         )
     )
 
+    if tasks.environment.dry_run:
+        return True
+
     attempts = 0
     server_ok = False
 
@@ -137,6 +148,8 @@ def is_mysql_running():
     return returncode == 0
 
 
+@task
+@timed
 def clear_mongo():
     """
     Clears mongo database.
@@ -148,6 +161,8 @@ def clear_mongo():
     )
 
 
+@task
+@timed
 def check_mongo():
     """
     Check that mongo is running
@@ -158,6 +173,8 @@ def check_mongo():
         sys.exit(1)
 
 
+@task
+@timed
 def check_memcache():
     """
     Check that memcache is running
@@ -168,6 +185,8 @@ def check_memcache():
         sys.exit(1)
 
 
+@task
+@timed
 def check_mysql():
     """
     Check that mysql is running
@@ -178,10 +197,11 @@ def check_mysql():
         sys.exit(1)
 
 
+@task
+@needs('check_mongo', 'check_memcache', 'check_mysql')
+@timed
 def check_services():
     """
     Check that all required services are running
     """
-    check_mongo()
-    check_memcache()
-    check_mysql()
+    pass

pavelib/utils/test/suites/acceptance_suite.py

 """
 Acceptance test suite
 """
-from paver.easy import sh, call_task
+from paver.easy import sh, call_task, task
 from pavelib.utils.test import utils as test_utils
 from pavelib.utils.test.suites.suite import TestSuite
 from pavelib.utils.envs import Env
+from pavelib.utils.timer import timed
 
 __test__ = False  # do not collect
 
 
+DBS = {
+    'default': Env.REPO_ROOT / 'test_root/db/test_edx.db',
+    'student_module_history': Env.REPO_ROOT / 'test_root/db/test_student_module_history.db'
+}
+DB_CACHES = {
+    'default': Env.REPO_ROOT / 'common/test/db_cache/lettuce.db',
+    'student_module_history': Env.REPO_ROOT / 'common/test/db_cache/lettuce_student_module_history.db'
+}
+
+
+@task
+@timed
+def setup_acceptance_db():
+    """
+    TODO: Improve the following
+
+    Since the CMS depends on the existence of some database tables
+    that are now in common but used to be in LMS (Role/Permissions for Forums)
+    we need to create/migrate the database tables defined in the LMS.
+    We might be able to address this by moving out the migrations from
+    lms/django_comment_client, but then we'd have to repair all the existing
+    migrations from the upgrade tables in the DB.
+    But for now for either system (lms or cms), use the lms
+    definitions to sync and migrate.
+    """
+
+    for db in DBS.keys():
+        if DBS[db].isfile():
+            # Since we are using SQLLite, we can reset the database by deleting it on disk.
+            DBS[db].remove()
+
+    if all(DB_CACHES[cache].isfile() for cache in DB_CACHES.keys()):
+        # To speed up migrations, we check for a cached database file and start from that.
+        # The cached database file should be checked into the repo
+
+        # Copy the cached database to the test root directory
+        for db_alias in DBS.keys():
+            sh("cp {db_cache} {db}".format(db_cache=DB_CACHES[db_alias], db=DBS[db_alias]))
+
+        # Run migrations to update the db, starting from its cached state
+        for db_alias in sorted(DBS.keys()):
+            # pylint: disable=line-too-long
+            sh("./manage.py lms --settings acceptance migrate --traceback --noinput --fake-initial --database {}".format(db_alias))
+            sh("./manage.py cms --settings acceptance migrate --traceback --noinput --fake-initial --database {}".format(db_alias))
+    else:
+        # If no cached database exists, syncdb before migrating, then create the cache
+        for db_alias in sorted(DBS.keys()):
+            sh("./manage.py lms --settings acceptance migrate --traceback --noinput --database {}".format(db_alias))
+            sh("./manage.py cms --settings acceptance migrate --traceback --noinput --database {}".format(db_alias))
+
+        # Create the cache if it doesn't already exist
+        for db_alias in DBS.keys():
+            sh("cp {db} {db_cache}".format(db_cache=DB_CACHES[db_alias], db=DBS[db_alias]))
+
+
 class AcceptanceTest(TestSuite):
     """
     A class for running lettuce acceptance tests.
@@ -67,14 +123,6 @@ class AcceptanceTestSuite(TestSuite):
     def __init__(self, *args, **kwargs):
         super(AcceptanceTestSuite, self).__init__(*args, **kwargs)
         self.root = 'acceptance'
-        self.dbs = {
-            'default': Env.REPO_ROOT / 'test_root/db/test_edx.db',
-            'student_module_history': Env.REPO_ROOT / 'test_root/db/test_student_module_history.db'
-        }
-        self.db_caches = {
-            'default': Env.REPO_ROOT / 'common/test/db_cache/lettuce.db',
-            'student_module_history': Env.REPO_ROOT / 'common/test/db_cache/lettuce_student_module_history.db'
-        }
         self.fasttest = kwargs.get('fasttest', False)
 
         if kwargs.get('system'):
@@ -102,46 +150,4 @@ class AcceptanceTestSuite(TestSuite):
             test_utils.clean_test_files()
 
         if not self.fasttest:
-            self._setup_acceptance_db()
-
-    def _setup_acceptance_db(self):
-        """
-        TODO: Improve the following
-
-        Since the CMS depends on the existence of some database tables
-        that are now in common but used to be in LMS (Role/Permissions for Forums)
-        we need to create/migrate the database tables defined in the LMS.
-        We might be able to address this by moving out the migrations from
-        lms/django_comment_client, but then we'd have to repair all the existing
-        migrations from the upgrade tables in the DB.
-        But for now for either system (lms or cms), use the lms
-        definitions to sync and migrate.
-        """
-
-        for db in self.dbs.keys():
-            if self.dbs[db].isfile():
-                # Since we are using SQLLite, we can reset the database by deleting it on disk.
-                self.dbs[db].remove()
-
-        if all(self.db_caches[cache].isfile() for cache in self.db_caches.keys()):
-            # To speed up migrations, we check for a cached database file and start from that.
-            # The cached database file should be checked into the repo
-
-            # Copy the cached database to the test root directory
-            for db_alias in self.dbs.keys():
-                sh("cp {db_cache} {db}".format(db_cache=self.db_caches[db_alias], db=self.dbs[db_alias]))
-
-            # Run migrations to update the db, starting from its cached state
-            for db_alias in sorted(self.dbs.keys()):
-                # pylint: disable=line-too-long
-                sh("./manage.py lms --settings acceptance migrate --traceback --noinput --fake-initial --database {}".format(db_alias))
-                sh("./manage.py cms --settings acceptance migrate --traceback --noinput --fake-initial --database {}".format(db_alias))
-        else:
-            # If no cached database exists, syncdb before migrating, then create the cache
-            for db_alias in sorted(self.dbs.keys()):
-                sh("./manage.py lms --settings acceptance migrate --traceback --noinput --database {}".format(db_alias))
-                sh("./manage.py cms --settings acceptance migrate --traceback --noinput --database {}".format(db_alias))
-
-            # Create the cache if it doesn't already exist
-            for db_alias in self.dbs.keys():
-                sh("cp {db} {db_cache}".format(db_cache=self.db_caches[db_alias], db=self.dbs[db_alias]))
+            setup_acceptance_db()

pavelib/utils/test/suites/bokchoy_suite.py

@@ -7,11 +7,20 @@ from urllib import urlencode
 from common.test.acceptance.fixtures.course import CourseFixture, FixtureError
 
 from path import Path as path
-from paver.easy import sh, BuildFailure
+from paver.easy import sh, BuildFailure, cmdopts, task, needs, might_call, call_task, dry
 from pavelib.utils.test.suites.suite import TestSuite
 from pavelib.utils.envs import Env
-from pavelib.utils.test import bokchoy_utils
+from pavelib.utils.test.bokchoy_utils import (
+    clear_mongo, start_servers, check_services, wait_for_test_servers
+)
+from pavelib.utils.test.bokchoy_options import (
+    BOKCHOY_IMPORTS_DIR, BOKCHOY_IMPORTS_DIR_DEPR,
+    BOKCHOY_DEFAULT_STORE, BOKCHOY_DEFAULT_STORE_DEPR,
+    BOKCHOY_FASTTEST,
+    PA11Y_FETCH_COURSE
+)
 from pavelib.utils.test import utils as test_utils
+from pavelib.utils.timer import timed
 
 import os
 
@@ -25,6 +34,135 @@ __test__ = False  # do not collect
 DEFAULT_NUM_PROCESSES = 1
 DEFAULT_VERBOSITY = 2
 
+DEMO_COURSE_TAR_GZ = "https://github.com/edx/demo-test-course/archive/master.tar.gz"
+DEMO_COURSE_IMPORT_DIR = path('test_root/courses/')
+
+
+@task
+@cmdopts([BOKCHOY_DEFAULT_STORE, BOKCHOY_DEFAULT_STORE_DEPR])
+@timed
+def load_bok_choy_data(options):
+    """
+    Loads data into database from db_fixtures
+    """
+    print 'Loading data from json fixtures in db_fixtures directory'
+    sh(
+        "DEFAULT_STORE={default_store}"
+        " ./manage.py lms --settings bok_choy loaddata --traceback"
+        " common/test/db_fixtures/*.json".format(
+            default_store=options.default_store,
+        )
+    )
+
+
+@task
+@cmdopts([
+    BOKCHOY_IMPORTS_DIR, BOKCHOY_IMPORTS_DIR_DEPR, BOKCHOY_DEFAULT_STORE,
+    BOKCHOY_DEFAULT_STORE_DEPR
+])
+@timed
+def load_courses(options):
+    """
+    Loads courses from options.imports_dir.
+
+    Note: options.imports_dir is the directory that contains the directories
+    that have courses in them. For example, if the course is located in
+    `test_root/courses/test-example-course/`, options.imports_dir should be
+    `test_root/courses/`.
+    """
+    if 'imports_dir' in options:
+        msg = colorize('green', "Importing courses from {}...".format(options.imports_dir))
+        print msg
+
+        sh(
+            "DEFAULT_STORE={default_store}"
+            " ./manage.py cms --settings=bok_choy import {import_dir}".format(
+                default_store=options.default_store,
+                import_dir=options.imports_dir
+            )
+        )
+    else:
+        print colorize('blue', "--imports-dir not set, skipping import")
+
+
+@task
+@cmdopts([BOKCHOY_IMPORTS_DIR, BOKCHOY_IMPORTS_DIR_DEPR, PA11Y_FETCH_COURSE])
+@timed
+def get_test_course(options):
+    """
+    Fetches the test course.
+    """
+
+    if options.get('imports_dir'):
+        print colorize("green", "--imports-dir specified, skipping fetch of test course")
+        return
+
+    if not options.get('should_fetch_course', False):
+        print colorize("green", "--skip-fetch specified, skipping fetch of test course")
+        return
+
+    # Set the imports_dir for use by other tasks
+    options.imports_dir = DEMO_COURSE_IMPORT_DIR
+
+    options.imports_dir.makedirs_p()
+    zipped_course = options.imports_dir + 'demo_course.tar.gz'
+
+    msg = colorize('green', "Fetching the test course from github...")
+    print msg
+
+    sh(
+        'wget {tar_gz_file} -O {zipped_course}'.format(
+            tar_gz_file=DEMO_COURSE_TAR_GZ,
+            zipped_course=zipped_course,
+        )
+    )
+
+    msg = colorize('green', "Uncompressing the test course...")
+    print msg
+
+    sh(
+        'tar zxf {zipped_course} -C {courses_dir}'.format(
+            zipped_course=zipped_course,
+            courses_dir=options.imports_dir,
+        )
+    )
+
+
+@task
+@timed
+def reset_test_database():
+    """
+    Reset the database used by the bokchoy tests.
+    """
+    sh("{}/scripts/reset-test-db.sh".format(Env.REPO_ROOT))
+
+
+@task
+@needs(['reset_test_database', 'clear_mongo', 'load_bok_choy_data', 'load_courses'])
+@might_call('start_servers')
+@cmdopts([BOKCHOY_FASTTEST], share_with=['start_servers'])
+@timed
+def prepare_bokchoy_run(options):
+    """
+    Sets up and starts servers for a Bok Choy run. If --fasttest is not
+    specified then static assets are collected
+    """
+    if not options.get('fasttest', False):
+
+        print colorize('green', "Generating optimized static assets...")
+        if options.get('log_dir') is None:
+            call_task('update_assets', args=['--settings', 'test_static_optimized'])
+        else:
+            call_task('update_assets', args=[
+                '--settings', 'test_static_optimized',
+                '--collect-log', options.log_dir
+            ])
+
+    # Ensure the test servers are available
+    msg = colorize('green', "Confirming servers are running...")
+    print msg
+    start_servers()  # pylint: disable=no-value-for-parameter
+
 
 class BokChoyTestSuite(TestSuite):
     """
@@ -73,29 +211,32 @@ class BokChoyTestSuite(TestSuite):
         self.log_dir.makedirs_p()
         self.har_dir.makedirs_p()
         self.report_dir.makedirs_p()
-        test_utils.clean_reports_dir()      # pylint: disable=no-value-for-parameter
+        test_utils.clean_reports_dir()  # pylint: disable=no-value-for-parameter
 
         if not (self.fasttest or self.skip_clean or self.testsonly):
             test_utils.clean_test_files()
 
         msg = colorize('green', "Checking for mongo, memchache, and mysql...")
         print msg
-        bokchoy_utils.check_services()
+        check_services()
 
         if not self.testsonly:
-            self.prepare_bokchoy_run()
+            call_task('prepare_bokchoy_run', options={'log_dir': self.log_dir})  # pylint: disable=no-value-for-parameter
         else:
             # load data in db_fixtures
-            self.load_data()
+            load_bok_choy_data()  # pylint: disable=no-value-for-parameter
 
         msg = colorize('green', "Confirming servers have started...")
         print msg
-        bokchoy_utils.wait_for_test_servers()
+        wait_for_test_servers()
         try:
             # Create course in order to seed forum data underneath. This is
             # a workaround for a race condition. The first time a course is created;
             # role permissions are set up for forums.
-            CourseFixture('foobar_org', '1117', 'seed_forum', 'seed_foo').install()
+            dry(
+                "Installing course fixture for forums",
+                CourseFixture('foobar_org', '1117', 'seed_forum', 'seed_foo').install
+            )
             print 'Forums permissions/roles data has been seeded'
         except FixtureError:
             # this means it's already been done
@@ -116,7 +257,7 @@ class BokChoyTestSuite(TestSuite):
             msg = colorize('green', "Cleaning up databases...")
             print msg
             sh("./manage.py lms --settings bok_choy flush --traceback --noinput")
-            bokchoy_utils.clear_mongo()
+            clear_mongo()
 
     @property
     def verbosity_processes_command(self):
@@ -147,66 +288,6 @@ class BokChoyTestSuite(TestSuite):
 
         return command
 
-    def prepare_bokchoy_run(self):
-        """
-        Sets up and starts servers for a Bok Choy run. If --fasttest is not
-        specified then static assets are collected
-        """
-        sh("{}/scripts/reset-test-db.sh".format(Env.REPO_ROOT))
-
-        if not self.fasttest:
-            self.generate_optimized_static_assets(log_dir=self.log_dir)
-
-        # Clear any test data already in Mongo or MySQLand invalidate
-        # the cache
-        bokchoy_utils.clear_mongo()
-        self.cache.flush_all()
-
-        # load data in db_fixtures
-        self.load_data()
-
-        # load courses if self.imports_dir is set
-        self.load_courses()
-
-        # Ensure the test servers are available
-        msg = colorize('green', "Confirming servers are running...")
-        print msg
-        bokchoy_utils.start_servers(self.default_store, self.coveragerc)
-
-    def load_courses(self):
-        """
-        Loads courses from self.imports_dir.
-
-        Note: self.imports_dir is the directory that contains the directories
-        that have courses in them. For example, if the course is located in
-        `test_root/courses/test-example-course/`, self.imports_dir should be
-        `test_root/courses/`.
-        """
-        msg = colorize('green', "Importing courses from {}...".format(self.imports_dir))
-        print msg
-
-        if self.imports_dir:
-            sh(
-                "DEFAULT_STORE={default_store}"
-                " ./manage.py cms --settings=bok_choy import {import_dir}".format(
-                    default_store=self.default_store,
-                    import_dir=self.imports_dir
-                )
-            )
-
-    def load_data(self):
-        """
-        Loads data into database from db_fixtures
-        """
-        print 'Loading data from json fixtures in db_fixtures directory'
-        sh(
-            "DEFAULT_STORE={default_store}"
-            " ./manage.py lms --settings bok_choy loaddata --traceback"
-            " common/test/db_fixtures/*.json".format(
-                default_store=self.default_store,
-            )
-        )
-
     def run_servers_continuously(self):
         """
         Infinite loop. Servers will continue to run in the current session unless interrupted.
@@ -268,21 +349,7 @@ class Pa11yCrawler(BokChoyTestSuite):
     def __init__(self, *args, **kwargs):
         super(Pa11yCrawler, self).__init__(*args, **kwargs)
         self.course_key = kwargs.get('course_key')
-        if self.imports_dir:
-            # If imports_dir has been specified, assume the files are
-            # already there -- no need to fetch them from github. This
-            # allows someome to crawl a different course. They are responsible
-            # for putting it, un-archived, in the directory.
-            self.should_fetch_course = False
-        else:
-            # Otherwise, obey `--skip-fetch` command and use the default
-            # test course.  Note that the fetch will also be skipped when
-            # using `--fast`.
-            self.should_fetch_course = kwargs.get('should_fetch_course')
-            self.imports_dir = path('test_root/courses/')
-
         self.pa11y_report_dir = os.path.join(self.report_dir, 'pa11ycrawler_reports')
-        self.tar_gz_file = "https://github.com/edx/demo-test-course/archive/master.tar.gz"
 
         self.start_urls = []
         auto_auth_params = {
@@ -304,38 +371,6 @@ class Pa11yCrawler(BokChoyTestSuite):
         lms_params = urlencode(auto_auth_params)
         self.start_urls.append("\"http://localhost:8003/auto_auth?{}\"".format(lms_params))
 
-    def __enter__(self):
-        if self.should_fetch_course:
-            self.get_test_course()
-        super(Pa11yCrawler, self).__enter__()
-
-    def get_test_course(self):
-        """
-        Fetches the test course.
-        """
-        self.imports_dir.makedirs_p()
-        zipped_course = self.imports_dir + 'demo_course.tar.gz'
-
-        msg = colorize('green', "Fetching the test course from github...")
-        print msg
-
-        sh(
-            'wget {tar_gz_file} -O {zipped_course}'.format(
-                tar_gz_file=self.tar_gz_file,
-                zipped_course=zipped_course,
-            )
-        )
-
-        msg = colorize('green', "Uncompressing the test course...")
-        print msg
-
-        sh(
-            'tar zxf {zipped_course} -C {courses_dir}'.format(
-                zipped_course=zipped_course,
-                courses_dir=self.imports_dir,
-            )
-        )
-
     def generate_html_reports(self):
         """
         Runs pa11ycrawler json-to-html

pavelib/utils/test/suites/suite.py

@@ -61,20 +61,6 @@ class TestSuite(object):
         """
         return None
 
-    def generate_optimized_static_assets(self, log_dir=None):
-        """
-        Collect static assets using test_static_optimized.py which generates
-        optimized files to a dedicated test static root. Optionally use
-        a log directory for collectstatic output.
-        """
-        print colorize('green', "Generating optimized static assets...")
-        if not log_dir:
-            sh("paver update_assets --settings=test_static_optimized")
-        else:
-            sh("paver update_assets --settings=test_static_optimized --collect-log={log_dir}".format(
-                log_dir=log_dir
-            ))
-
     def run_test(self):
         """
         Runs a self.cmd in a subprocess and waits for it to finish.

pavelib/utils/test/utils.py

@@ -3,6 +3,7 @@ Helper functions for test tasks
 """
 from paver.easy import sh, task, cmdopts
 from pavelib.utils.envs import Env
+from pavelib.utils.timer import timed
 import os
 import re
 import subprocess
@@ -15,6 +16,7 @@ __test__ = False  # do not collect
 
 
 @task
+@timed
 def clean_test_files():
     """
     Clean fixture files used by tests and .pyc files
@@ -42,6 +44,7 @@ def clean_dir(directory):
     ('skip-clean', 'C', 'skip cleaning repository before running tests'),
     ('skip_clean', None, 'deprecated in favor of skip-clean'),
 ])
+@timed
 def clean_reports_dir(options):
     """
     Clean coverage files, to ensure that we don't use stale data to generate reports.
@@ -57,6 +60,7 @@ def clean_reports_dir(options):
 
 
 @task
+@timed
 def clean_mongo():
     """
     Clean mongo test databases

pavelib/utils/timer.py

+"""
+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")