add query debug support

fixes #24

Author: timgraham

django_mongodb/base.py

@@ -11,6 +11,7 @@
 from .introspection import DatabaseIntrospection
 from .operations import DatabaseOperations
 from .schema import DatabaseSchemaEditor
+from .utils import CollectionDebugWrapper
 
 
 class Cursor:
@@ -74,7 +75,10 @@ def __init__(self, *args, **kwargs):
         del self.connection
 
     def get_collection(self, name, **kwargs):
-        return Collection(self.database, name, **kwargs)
+        collection = Collection(self.database, name, **kwargs)
+        if self.queries_logged:
+            collection = CollectionDebugWrapper(collection, self)
+        return collection
 
     def __getattr__(self, attr):
         """

django_mongodb/compiler.py

@@ -1,11 +1,5 @@
-from django.conf import settings
 from django.core.exceptions import EmptyResultSet
-from django.db import (
-    DatabaseError,
-    IntegrityError,
-    NotSupportedError,
-    connections,
-)
+from django.db import DatabaseError, IntegrityError, NotSupportedError
 from django.db.models import NOT_PROVIDED, Count, Expression, Value
 from django.db.models.aggregates import Aggregate
 from django.db.models.constants import LOOKUP_SEP
@@ -144,11 +138,6 @@ def build_query(self, columns=None):
         query = self.query_class(self, columns)
         query.add_filters(self.query.where)
         query.order_by(self._get_ordering())
-
-        # This at least satisfies the most basic unit tests.
-        force_debug_cursor = connections[self.using].force_debug_cursor
-        if force_debug_cursor or (force_debug_cursor is None and settings.DEBUG):
-            self.connection.queries_log.append({"sql": repr(query)})
         return query
 
     def get_columns(self):

django_mongodb/features.py

@@ -11,9 +11,9 @@ class DatabaseFeatures(BaseDatabaseFeatures):
     uses_savepoints = False
 
     django_test_expected_failures = {
-        "basic.tests.ModelInstanceCreationTests.test_save_parent_primary_with_default",
+        # Database defaults not supported: bson.errors.InvalidDocument:
+        # cannot encode object: <django.db.models.expressions.DatabaseDefault
         "basic.tests.ModelInstanceCreationTests.test_save_primary_with_db_default",
-        "basic.tests.ModelInstanceCreationTests.test_save_primary_with_default",
         # Date lookups aren't implemented: https://github.com/mongodb-labs/django-mongodb/issues/9
         # (e.g. 'ExtractMonth' object has no attribute 'alias')
         "basic.tests.ModelLookupTest.test_does_not_exist",

django_mongodb/utils.py

@@ -1,6 +1,12 @@
+import copy
+import time
+
 import django
+from django.conf import settings
 from django.core.exceptions import ImproperlyConfigured
+from django.db.backends.utils import logger
 from django.utils.version import get_version_tuple
+from pymongo.cursor import Cursor
 
 
 def check_django_compatability():
@@ -18,3 +24,89 @@ def check_django_compatability():
             f"You must use the latest version of django-mongodb {A}.{B}.x "
             f"with Django {A}.{B}.y (found django-mongodb {__version__})."
         )
+
+
+class CollectionDebugWrapper:
+    def __init__(self, collection, db):
+        self.collection = collection
+        self.db = db
+
+    def __getattr__(self, attr):
+        return getattr(self.collection, attr)
+
+    def profile_call(self, func, args=(), kwargs=None):
+        start = time.monotonic()
+        retval = func(*args, **kwargs or {})
+        duration = time.monotonic() - start
+        return duration, retval
+
+    def log(self, op, duration, args, kwargs=None):
+        msg = "(%.3f) %s"
+        args = " ".join(str(arg) for arg in args)
+        operation = f"{self.collection.name}.{op}({args})"
+        kwargs = {k: v for k, v in kwargs.items() if v}
+        if kwargs:
+            operation += f"; kwargs={kwargs}"
+        if len(settings.DATABASES) > 1:
+            msg += f"; alias={self.db.alias}"
+        self.db.queries_log.append(
+            {
+                "sql": operation,
+                "time": "%.3f" % duration,
+            }
+        )
+        logger.debug(
+            msg,
+            duration,
+            operation,
+            extra={
+                "duration": duration,
+                "sql": operation,
+                "kwargs": kwargs,
+                "alias": self.db.alias,
+            },
+        )
+
+    def find(self, *args, **kwargs):
+        return DebugCursor(self, self.collection, *args, **kwargs)
+
+    def logging_wrapper(method):
+        def wrapper(self, *args, **kwargs):
+            func = getattr(self.collection, method)
+            # Collection.insert_one() mutates args[0] (the document) by adding
+            # the _id. deepcopy() to avoid logging that version.
+            original_args = copy.deepcopy(args)
+            duration, retval = self.profile_call(func, args, kwargs)
+            self.log(method, duration, original_args, kwargs)
+            return retval
+
+        return wrapper
+
+    # These are the operations that this backend uses.
+    count_documents = logging_wrapper("count_documents")
+    insert_one = logging_wrapper("insert_one")
+    delete_many = logging_wrapper("delete_many")
+    update_many = logging_wrapper("update_many")
+
+    del logging_wrapper
+
+
+class DebugCursor(Cursor):
+    def __init__(self, collection_wrapper, *args, **kwargs):
+        self.collection_wrapper = collection_wrapper
+        super().__init__(*args, **kwargs)
+
+    def _refresh(self):
+        super_method = super()._refresh
+        if self._Cursor__id is not None:
+            return super_method()
+        # self.__id is None: first time the .find() iterator is
+        # entered. find() profiling happens here.
+        duration, retval = self.collection_wrapper.profile_call(super_method)
+        kwargs = {
+            "limit": self._Cursor__limit,
+            "skip": self._Cursor__skip,
+            "sort": self._Cursor__ordering,
+        }
+        self.collection_wrapper.log("find", duration, [self._Cursor__spec], kwargs)
+        return retval