Make ZOPE_INTERFACE_STRICT_IRO imply ZOPE_INTERFACE_LOG_CHANGED_IRO.issue229

This helps diagnosing problems when just strict mode isn't enough, and strict mode is the one that's being used most of the time.

Fixes #229

5 files changed, 70 insertions, 6 deletions

diff --git a/CHANGES.rst b/CHANGES.rst
index ff3254c..1d741cb 100644
--- a/CHANGES.rst
+++ b/CHANGES.rst
@@ -5,6 +5,14 @@
 5.3.0 (unreleased)
 ==================
 
+- Make the debug environment variable ``ZOPE_INTERFACE_STRICT_IRO``
+  imply ``ZOPE_INTERFACE_LOG_CHANGED_IRO``. See
+  `issue 229 <https://github.com/zopefoundation/zope.interface/issues/229>`_.
+
+- Improve the repr of ``zope.interface.Provides`` to remove ambiguity
+  about what is being provided. This is especially helpful diagnosing
+  IRO issues.
+
 - Allow subclasses of ``BaseAdapterRegistry`` (including
   ``AdapterRegistry`` and ``VerifyingAdapterRegistry``) to have
   control over the data structures. This allows persistent
diff --git a/src/zope/interface/declarations.py b/src/zope/interface/declarations.py
index 9a0146c..5f9cc52 100644
--- a/src/zope/interface/declarations.py
+++ b/src/zope/interface/declarations.py
@@ -750,10 +750,11 @@ class Provides(Declaration):  # Really named ProvidesClass
         Declaration.__init__(self, *(interfaces + (implementedBy(cls), )))
 
     def __repr__(self):
-        return "<%s.%s for %s>" % (
+        return "<%s.%s for instances of %s providing %s>" % (
             self.__class__.__module__,
             self.__class__.__name__,
             self._cls,
+            self.__args[1:]
         )
 
     def __reduce__(self):
diff --git a/src/zope/interface/ro.py b/src/zope/interface/ro.py
index 20338ed..a801922 100644
--- a/src/zope/interface/ro.py
+++ b/src/zope/interface/ro.py
@@ -45,17 +45,27 @@ ZOPE_INTERFACE_STRICT_IRO
     If this is set to "1", any attempt to use :func:`ro` that would produce a non-C3
     ordering will fail by raising :class:`InconsistentResolutionOrderError`.
 
-There are two environment variables that are independent.
+    This also has the effect of setting
+    ``ZOPE_INTERFACE_LOG_CHANGED_IRO``. Sometimes a resolution order
+    can successfully be made C3-compliant but still change in such a
+    way that the end result is unexpected, so this logging can help find such
+    subtle problems.
+
+There are two environment variables that are generally independent.
 
 ZOPE_INTERFACE_LOG_CHANGED_IRO
     If this is set to "1", then if the C3 resolution order is different from
     the legacy resolution order for any given object, a message explaining the differences
-    will be logged. This is intended to be used for debugging complicated IROs.
+    will be logged from the logger named for this package.
+    This is intended to be used for debugging complicated IROs.
 ZOPE_INTERFACE_USE_LEGACY_IRO
     If this is set to "1", then the C3 resolution order will *not* be used. The
     legacy IRO will be used instead. This is a temporary measure and will be removed in the
     future. It is intended to help during the transition.
     It implies ``ZOPE_INTERFACE_LOG_CHANGED_IRO``.
+
+.. versionchanged:: 5.3.0
+   Setting ``ZOPE_INTERFACE_STRICT_IRO`` implies ``ZOPE_INTERFACE_LOG_CHANGED_IRO``.
 """
 from __future__ import print_function
 __docformat__ = 'restructuredtext'
@@ -235,6 +245,8 @@ class C3(object):
     __mro = None
     __legacy_ro = None
     direct_inconsistency = False
+    # Did we operate in strict mode?
+    strict = False
 
     def __init__(self, C, memo):
         self.leaf = C
@@ -420,6 +432,7 @@ class C3(object):
 
 class _StrictC3(C3):
     __slots__ = ()
+    strict = True
     def _guess_next_base(self, base_tree_remaining):
         raise InconsistentResolutionOrderError(self, base_tree_remaining)
 
@@ -594,13 +607,20 @@ def ro(C, strict=None, base_mros=None, log_changed_ro=None, use_legacy_ro=None):
        Add the *strict*, *log_changed_ro* and *use_legacy_ro*
        keyword arguments. These are provisional and likely to be
        removed in the future. They are most useful for testing.
+    .. versionchanged:: 5.3.0
+       Setting *strict* to True implies *log_changed_ro* *unless*
+       *log_changed_ro* is explicitly set.
     """
     # The ``base_mros`` argument is for internal optimization and
     # not documented.
     resolver = C3.resolver(C, strict, base_mros)
     mro = resolver.mro()
 
-    log_changed = log_changed_ro if log_changed_ro is not None else resolver.LOG_CHANGED_IRO
+    log_changed = (
+        log_changed_ro
+        if log_changed_ro is not None
+        else resolver.LOG_CHANGED_IRO or resolver.strict
+    )
     use_legacy = use_legacy_ro if use_legacy_ro is not None else resolver.USE_LEGACY_IRO
 
     if log_changed or use_legacy:
@@ -617,6 +637,11 @@ def ro(C, strict=None, base_mros=None, log_changed_ro=None, use_legacy_ro=None):
             changed = legacy_without_root != mro_without_root
 
         if changed:
+            # TODO: It would be nice to see if any of the ancestors
+            # produced an invalid resolution order that was fixed up by
+            # using the C3 ordering; those are the ones where changes are
+            # likely to be the biggest. They can have impacts far downstream
+            # even if strict mode is true.
             comparison = _ROComparison(resolver, mro, legacy_ro)
             _logger().warning(
                 "Object %r has different legacy and C3 MROs:\n%s",
diff --git a/src/zope/interface/tests/test_declarations.py b/src/zope/interface/tests/test_declarations.py
index 9ef192a..4b48496 100644
--- a/src/zope/interface/tests/test_declarations.py
+++ b/src/zope/interface/tests/test_declarations.py
@@ -1305,10 +1305,16 @@ class ProvidesClassTests(unittest.TestCase):
         self.assertRaises(AttributeError, _test)
 
     def test__repr__(self):
-        inst = self._makeOne(type(self))
+        from zope.interface.interface import InterfaceClass
+        IFoo = InterfaceClass("IFoo")
+
+        inst = self._makeOne(type(self), IFoo)
         self.assertEqual(
             repr(inst),
-            "<zope.interface.Provides for %r>"  % type(self)
+            "<zope.interface.Provides for instances of %r providing %s>"  % (
+                type(self),
+                (IFoo,)
+            )
         )
 
 
diff --git a/src/zope/interface/tests/test_ro.py b/src/zope/interface/tests/test_ro.py
index 61f92b6..a1e6947 100644
--- a/src/zope/interface/tests/test_ro.py
+++ b/src/zope/interface/tests/test_ro.py
@@ -221,6 +221,9 @@ class Test_c3_ro(Test_ro):
         if hasattr(A, 'mro'):
             self.assertEqual(A.mro(), self._callFUT(A))
 
+        # Clear anything the ro module logged by default,
+        # which might depend on environment variables.
+        self.log_handler.clear()
         return A
 
     def test_complex_diamond_interface(self):
@@ -252,6 +255,27 @@ class Test_c3_ro(Test_ro):
         self.assertEqual(tuple(computed_A_iro), A.__iro__)
         self._check_handler_complex_diamond()
 
+    def test_complex_diamond_strict_argument(self):
+        from zope.interface import Interface
+
+        A = self.test_complex_diamond(Interface)
+        computed_A_iro = self._callFUT(A, strict=True)
+        # It matches, of course, but strict mode implies
+        # that we also log changes.
+        self.assertEqual(tuple(computed_A_iro), A.__iro__)
+        self._check_handler_complex_diamond()
+
+    def test_complex_diamond_strict_and_log_arguments(self):
+        from zope.interface import Interface
+
+        A = self.test_complex_diamond(Interface)
+        computed_A_iro = self._callFUT(A, strict=True, log_changed_ro=False)
+        # It matches, of course...
+        self.assertEqual(tuple(computed_A_iro), A.__iro__)
+        # ...but because we explicitly set log_changed_ro to False,
+        # nothing is logged
+        self.assertFalse(self.log_handler.records)
+
     def _check_handler_complex_diamond(self):
         handler = self.log_handler
         self.assertEqual(1, len(handler.records))