remove loader depth warning, replace with logging message

Replaced the "loader depth is excessively deep" warning with a shorter
message added to the caching badge within SQL logging, for those statements
where the ORM disabled the cache due to a too-deep chain of loader options.
The condition which this warning highlights is difficult to resolve and is
generally just a limitation in the ORM's application of SQL caching. A
future feature may include the ability to tune the threshold where caching
is disabled, but for now the warning will no longer be a nuisance.

Fixes: #10896
Change-Id: Ic3be2086d1db16f9a75390323f00a43ef72aca12

diff --git a/doc/build/changelog/unreleased_20/10896.rst b/doc/build/changelog/unreleased_20/10896.rst
new file mode 100644 (file)
index 0000000..77224d9
--- /dev/null
+++ b/doc/build/changelog/unreleased_20/10896.rst
@@ -0,0 +1,11 @@
+.. change::
+    :tags: bug, orm
+    :tickets: 10896
+
+    Replaced the "loader depth is excessively deep" warning with a shorter
+    message added to the caching badge within SQL logging, for those statements
+    where the ORM disabled the cache due to a too-deep chain of loader options.
+    The condition which this warning highlights is difficult to resolve and is
+    generally just a limitation in the ORM's application of SQL caching. A
+    future feature may include the ability to tune the threshold where caching
+    is disabled, but for now the warning will no longer be a nuisance.

diff --git a/lib/sqlalchemy/engine/default.py b/lib/sqlalchemy/engine/default.py
index 213a047711eb84b601ff5d2da05d4a86de598f91..afbda08b46172eaea273c14cacb0aa796a096f85 100644 (file)
--- a/lib/sqlalchemy/engine/default.py
+++ b/lib/sqlalchemy/engine/default.py
@@ -1583,7 +1583,13 @@ class DefaultExecutionContext(ExecutionContext):
         elif ch is CACHE_MISS:
             return "generated in %.5fs" % (now - gen_time,)
         elif ch is CACHING_DISABLED:
-            return "caching disabled %.5fs" % (now - gen_time,)
+            if "_cache_disable_reason" in self.execution_options:
+                return "caching disabled (%s) %.5fs " % (
+                    self.execution_options["_cache_disable_reason"],
+                    now - gen_time,
+                )
+            else:
+                return "caching disabled %.5fs" % (now - gen_time,)
         elif ch is NO_DIALECT_SUPPORT:
             return "dialect %s+%s does not support caching %.5fs" % (
                 self.dialect.name,

diff --git a/lib/sqlalchemy/orm/context.py b/lib/sqlalchemy/orm/context.py
index 7ab7e6279eabb2ee64f289ec723160345637549c..b417825318531fb2adfb428da58fc20c8d487130 100644 (file)
--- a/lib/sqlalchemy/orm/context.py
+++ b/lib/sqlalchemy/orm/context.py
@@ -517,15 +517,14 @@ class ORMCompileState(AbstractORMCompileState):
             and len(statement._compile_options._current_path) > 10
             and execution_options.get("compiled_cache", True) is not None
         ):
-            util.warn(
-                "Loader depth for query is excessively deep; caching will "
-                "be disabled for additional loaders.   For recursive eager "
-                "loaders consider using the recursion_depth feature.  "
-                "Use the compiled_cache=None execution option to "
-                "skip this warning."
-            )
-            execution_options = execution_options.union(
-                {"compiled_cache": None}
+            execution_options: util.immutabledict[
+                str, Any
+            ] = execution_options.union(
+                {
+                    "compiled_cache": None,
+                    "_cache_disable_reason": "excess depth for "
+                    "ORM loader options",
+                }
             )
 
         bind_arguments["clause"] = statement

diff --git a/test/orm/test_recursive_loaders.py b/test/orm/test_recursive_loaders.py
index 10582e71131f5c01e092ab672c6c434d35ace3d4..e6ce5ccd7eff0ff38c503e4af76dd84ade1da42c 100644 (file)
--- a/test/orm/test_recursive_loaders.py
+++ b/test/orm/test_recursive_loaders.py
@@ -1,3 +1,5 @@
+import logging.handlers
+
 import sqlalchemy as sa
 from sqlalchemy import ForeignKey
 from sqlalchemy import Integer
@@ -11,7 +13,6 @@ from sqlalchemy.orm import selectinload
 from sqlalchemy.orm import Session
 from sqlalchemy.testing import eq_
 from sqlalchemy.testing import expect_raises_message
-from sqlalchemy.testing import expect_warnings
 from sqlalchemy.testing import fixtures
 from sqlalchemy.testing.fixtures import fixture_session
 from sqlalchemy.testing.schema import Column
@@ -258,13 +259,27 @@ class DeepRecursiveTest(_NodeTest, fixtures.MappedTest):
                 result = s.scalars(stmt)
                 self._assert_depth(result.one(), 200)
 
+    @testing.fixture
+    def capture_log(self, testing_engine):
+        existing_level = logging.getLogger("sqlalchemy.engine").level
+
+        buf = logging.handlers.BufferingHandler(100)
+        logging.getLogger("sqlalchemy.engine").addHandler(buf)
+        logging.getLogger("sqlalchemy.engine").setLevel(logging.INFO)
+        yield buf
+        logging.getLogger("sqlalchemy.engine").setLevel(existing_level)
+        logging.getLogger("sqlalchemy.engine").removeHandler(buf)
+
     @testing.combinations(selectinload, immediateload, argnames="loader_fn")
     @testing.combinations(4, 9, 12, 25, 41, 55, argnames="depth")
     @testing.variation("disable_cache", [True, False])
     def test_warning_w_no_recursive_opt(
-        self, loader_fn, depth, limited_cache_conn, disable_cache
+        self, loader_fn, depth, limited_cache_conn, disable_cache, capture_log
     ):
+        buf = capture_log
+
         connection = limited_cache_conn(27)
+        connection._echo = True
 
         Node = self.classes.Node
 
@@ -280,21 +295,24 @@ class DeepRecursiveTest(_NodeTest, fixtures.MappedTest):
             else:
                 exec_opts = {}
 
-            # note this is a magic number, it's not important that it's exact,
-            # just that when someone makes a huge recursive thing,
-            # it warns
-            if depth > 8 and not disable_cache:
-                with expect_warnings(
-                    "Loader depth for query is excessively deep; "
-                    "caching will be disabled for additional loaders."
-                ):
-                    with Session(connection) as s:
-                        result = s.scalars(stmt, execution_options=exec_opts)
-                        self._assert_depth(result.one(), depth)
-            else:
-                with Session(connection) as s:
-                    result = s.scalars(stmt, execution_options=exec_opts)
-                    self._assert_depth(result.one(), depth)
+            with Session(connection) as s:
+                result = s.scalars(stmt, execution_options=exec_opts)
+                self._assert_depth(result.one(), depth)
+
+            if not disable_cache:
+                # note this is a magic number, it's not important that it's
+                # exact, just that when someone makes a huge recursive thing,
+                # it disables caching and notes in the logs
+                if depth > 8:
+                    eq_(
+                        buf.buffer[-1].message[0:55],
+                        "[caching disabled (excess depth for "
+                        "ORM loader options)",
+                    )
+                else:
+                    assert buf.buffer[-1].message.startswith(
+                        "[cached since" if i > 0 else "[generated in"
+                    )
 
         if disable_cache:
             clen = len(connection.engine._compiled_cache)