Improve debuggability when call-count numbers don't match up

cms/djangoapps/contentstore/tests/test_contentstore.py

@@ -867,7 +867,7 @@ class ContentStoreToyCourseTest(ContentStoreTestCase):
         # so we don't need to make an extra query to compute it.
         # set the branch to 'publish' in order to prevent extra lookups of draft versions
         with mongo_store.branch_setting(ModuleStoreEnum.Branch.published_only):
-            with check_mongo_calls(mongo_store, 4, 0):
+            with check_mongo_calls(4, 0):
                 course = mongo_store.get_course(course_id, depth=2)
 
             # make sure we pre-fetched a known sequential which should be at depth=2
@@ -879,7 +879,7 @@ class ContentStoreToyCourseTest(ContentStoreTestCase):
         # Now, test with the branch set to draft. No extra round trips b/c it doesn't go deep enough to get
         # beyond direct only categories
         with mongo_store.branch_setting(ModuleStoreEnum.Branch.draft_preferred):
-            with check_mongo_calls(mongo_store, 4, 0):
+            with check_mongo_calls(4, 0):
                 mongo_store.get_course(course_id, depth=2)
 
     def test_export_course_without_content_store(self):

cms/djangoapps/contentstore/tests/test_course_listing.py

@@ -201,10 +201,11 @@ class TestCourseListing(ModuleStoreTestCase):
 
         # Now count the db queries
         store = modulestore()._get_modulestore_by_type(ModuleStoreEnum.Type.mongo)
-        with check_mongo_calls(store, USER_COURSES_COUNT):
+        with check_mongo_calls(USER_COURSES_COUNT):
             _accessible_courses_list_from_groups(self.request)
 
-        with check_mongo_calls(store, 1):
+        # TODO: LMS-11220: Document why this takes 6 calls
+        with check_mongo_calls(6):
             _accessible_courses_list(self.request)
 
     def test_get_course_list_with_same_course_id(self):

common/lib/xmodule/xmodule/modulestore/tests/factories.py

+import pprint
+import pymongo.message
+
 from factory import Factory, lazy_attribute_sequence, lazy_attribute
 from factory.containers import CyclicDefinitionError
 from uuid import uuid4
@@ -223,79 +226,74 @@ def check_exact_number_of_calls(object_with_method, method, num_calls, method_na
         yield
 
 
-@contextmanager
-def check_number_of_calls(object_with_method, method, maximum_calls, minimum_calls=1, method_name=None):
+def check_number_of_calls(object_with_method, method_name, maximum_calls, minimum_calls=1):
     """
     Instruments the given method on the given object to verify the number of calls to the method is
     less than or equal to the expected maximum_calls and greater than or equal to the expected minimum_calls.
     """
-    method_wrap = Mock(wraps=method)
-    wrap_patch = patch.object(object_with_method, method_name or method.__name__, method_wrap)
+    return check_sum_of_calls(object_with_method, [method_name], maximum_calls, minimum_calls)
+
 
-    try:
-        wrap_patch.start()
+@contextmanager
+def check_sum_of_calls(object_, methods, maximum_calls, minimum_calls=1):
+    """
+    Instruments the given methods on the given object to verify that the total sum of calls made to the
+    methods falls between minumum_calls and maximum_calls.
+    """
+    mocks = {
+        method: Mock(wraps=getattr(object_, method))
+        for method in methods
+    }
+
+    with patch.multiple(object_, **mocks):
         yield
 
-    finally:
-        wrap_patch.stop()
+    call_count = sum(mock.call_count for mock in mocks.values())
+    calls = pprint.pformat({
+        method_name: mock.call_args_list
+        for method_name, mock in mocks.items()
+    })
+
+    # Assertion errors don't handle multi-line values, so pretty-print to std-out instead
+    if not minimum_calls <= call_count <= maximum_calls:
+        print "Expected between {} and {} calls, {} were made. Calls: {}".format(
+            minimum_calls,
+            maximum_calls,
+            call_count,
+            calls,
+        )
 
-        # verify the counter actually worked by ensuring we have counted greater than (or equal to) the minimum calls
-        assert_greater_equal(method_wrap.call_count, minimum_calls)
+    # verify the counter actually worked by ensuring we have counted greater than (or equal to) the minimum calls
+    assert_greater_equal(call_count, minimum_calls)
 
-        # now verify the number of actual calls is less than (or equal to) the expected maximum
-        assert_less_equal(method_wrap.call_count, maximum_calls)
+    # now verify the number of actual calls is less than (or equal to) the expected maximum
+    assert_less_equal(call_count, maximum_calls)
 
 
 @contextmanager
-def check_mongo_calls(mongo_store, num_finds=0, num_sends=None):
+def check_mongo_calls(num_finds=0, num_sends=None):
     """
     Instruments the given store to count the number of calls to find (incl find_one) and the number
     of calls to send_message which is for insert, update, and remove (if you provide num_sends). At the
     end of the with statement, it compares the counts to the num_finds and num_sends.
 
-    :param mongo_store: the MongoModulestore or subclass to watch or a SplitMongoModuleStore
     :param num_finds: the exact number of find calls expected
     :param num_sends: If none, don't instrument the send calls. If non-none, count and compare to
         the given int value.
     """
-    if mongo_store.get_modulestore_type() == ModuleStoreEnum.Type.mongo:
-        with check_exact_number_of_calls(mongo_store.collection, mongo_store.collection.find, num_finds):
-            if num_sends is not None:
-                with check_exact_number_of_calls(
-                    mongo_store.database.connection,
-                    mongo_store.database.connection._send_message,  # pylint: disable=protected-access
-                    num_sends,
-                ):
-                    yield
-            else:
+    with check_sum_of_calls(
+        pymongo.message,
+        ['query', 'get_more'],
+        num_finds,
+        num_finds
+    ):
+        if num_sends is not None:
+            with check_sum_of_calls(
+                pymongo.message,
+                ['insert', 'update', 'delete'],
+                num_sends,
+                num_sends
+            ):
                 yield
-    elif mongo_store.get_modulestore_type() == ModuleStoreEnum.Type.split:
-        collections = [
-            mongo_store.db_connection.course_index,
-            mongo_store.db_connection.structures,
-            mongo_store.db_connection.definitions,
-        ]
-        # could add else clause which raises exception or just rely on the below to suss that out
-        try:
-            find_wraps = []
-            wrap_patches = []
-            for collection in collections:
-                find_wrap = Mock(wraps=collection.find)
-                find_wraps.append(find_wrap)
-                wrap_patch = patch.object(collection, 'find', find_wrap)
-                wrap_patches.append(wrap_patch)
-                wrap_patch.start()
-            if num_sends is not None:
-                connection = mongo_store.db_connection.database.connection
-                with check_exact_number_of_calls(
-                    connection,
-                    connection._send_message,  # pylint: disable=protected-access
-                    num_sends,
-                ):
-                    yield
-            else:
-                yield
-        finally:
-            map(lambda wrap_patch: wrap_patch.stop(), wrap_patches)
-            call_count = sum([find_wrap.call_count for find_wrap in find_wraps])
-            assert_equal(call_count, num_finds)
+        else:
+            yield

common/lib/xmodule/xmodule/modulestore/tests/test_publish.py

@@ -19,23 +19,35 @@ class TestPublish(SplitWMongoCourseBoostrapper):
         # There are 12 created items and 7 parent updates
         # create course: finds: 1 to verify uniqueness, 1 to find parents
         # sends: 1 to create course, 1 to create overview
-        with check_mongo_calls(self.draft_mongo, 5, 2):
+        with check_mongo_calls(5, 2):
             super(TestPublish, self)._create_course(split=False)  # 2 inserts (course and overview)
 
         # with bulk will delay all inheritance computations which won't be added into the mongo_calls
         with self.draft_mongo.bulk_write_operations(self.old_course_key):
             # finds: 1 for parent to add child
             # sends: 1 for insert, 1 for parent (add child)
-            with check_mongo_calls(self.draft_mongo, 1, 2):
+            with check_mongo_calls(1, 2):
                 self._create_item('chapter', 'Chapter1', {}, {'display_name': 'Chapter 1'}, 'course', 'runid', split=False)
 
-            with check_mongo_calls(self.draft_mongo, 2, 2):
+            with check_mongo_calls(2, 2):
                 self._create_item('chapter', 'Chapter2', {}, {'display_name': 'Chapter 2'}, 'course', 'runid', split=False)
-            # update info propagation is 2 levels. create looks for draft and then published and then creates
-            with check_mongo_calls(self.draft_mongo, 8, 6):
+            # For each vertical (2) created:
+            #   - load draft
+            #   - load non-draft
+            #   - get last error
+            #   - load parent
+            #   - load inheritable data
+            with check_mongo_calls(10, 6):
                 self._create_item('vertical', 'Vert1', {}, {'display_name': 'Vertical 1'}, 'chapter', 'Chapter1', split=False)
                 self._create_item('vertical', 'Vert2', {}, {'display_name': 'Vertical 2'}, 'chapter', 'Chapter1', split=False)
-            with check_mongo_calls(self.draft_mongo, 20, 12):
+            # For each (4) item created
+            #   - load draft
+            #   - load non-draft
+            #   - get last error
+            #   - load parent
+            #   - load inheritable data
+            #   - load parent
+            with check_mongo_calls(24, 12):
                 self._create_item('html', 'Html1', "<p>Goodbye</p>", {'display_name': 'Parented Html'}, 'vertical', 'Vert1', split=False)
                 self._create_item(
                     'discussion', 'Discussion1',
@@ -63,7 +75,7 @@ class TestPublish(SplitWMongoCourseBoostrapper):
                     split=False
                 )
 
-            with check_mongo_calls(self.draft_mongo, 0, 2):
+            with check_mongo_calls(0, 2):
                 # 2 finds b/c looking for non-existent parents
                 self._create_item('static_tab', 'staticuno', "<p>tab</p>", {'display_name': 'Tab uno'}, None, None, split=False)
                 self._create_item('course_info', 'updates', "<ol><li><h2>Sep 22</h2><p>test</p></li></ol>", {}, None, None, split=False)
@@ -76,10 +88,11 @@ class TestPublish(SplitWMongoCourseBoostrapper):
         vert_location = self.old_course_key.make_usage_key('vertical', block_id='Vert1')
         item = self.draft_mongo.get_item(vert_location, 2)
         # Vert1 has 3 children; so, publishes 4 nodes which may mean 4 inserts & 1 bulk remove
+        # TODO: LMS-11220: Document why find count is 25
         # 25-June-2014 find calls are 19. Probably due to inheritance recomputation?
         # 02-July-2014 send calls are 7. 5 from above, plus 2 for updating subtree edit info for Chapter1 and course
         #              find calls are 22. 19 from above, plus 3 for finding the parent of Vert1, Chapter1, and course
-        with check_mongo_calls(self.draft_mongo, 22, 7):
+        with check_mongo_calls(25, 7):
             self.draft_mongo.publish(item.location, self.user_id)
 
         # verify status

common/lib/xmodule/xmodule/modulestore/xml_importer.py

@@ -607,7 +607,7 @@ def _import_course_draft(
                     _import_module(descriptor)
 
                 except Exception:
-                    logging.exception('There while importing draft descriptor %s', descriptor)
+                    logging.exception('while importing draft descriptor %s', descriptor)
 
 
 def allowed_metadata_by_category(category):

lms/djangoapps/courseware/tests/test_module_render.py

@@ -326,7 +326,7 @@ class TestTOC(ModuleStoreTestCase):
         self.request = factory.get(chapter_url)
         self.request.user = UserFactory()
         self.modulestore = self.store._get_modulestore_for_courseid(self.course_key)
-        with check_mongo_calls(self.modulestore, num_finds, num_sends):
+        with check_mongo_calls(num_finds, num_sends):
             self.toy_course = self.store.get_course(self.toy_loc, depth=2)
             self.field_data_cache = FieldDataCache.cache_for_descriptor_descendents(
                 self.toy_loc, self.request.user, self.toy_course, depth=2)
@@ -352,7 +352,7 @@ class TestTOC(ModuleStoreTestCase):
                             'format': '', 'due': None, 'active': False}],
                           'url_name': 'secret:magic', 'display_name': 'secret:magic'}])
 
-            with check_mongo_calls(self.modulestore, 0, 0):
+            with check_mongo_calls(0, 0):
                 actual = render.toc_for_course(
                     self.request.user, self.request, self.toy_course, self.chapter, None, self.field_data_cache
                 )