directlyProvides doesn't log changed resolution orders

[jamadden]

When debugging zopefoundation/zc.resourcelibrary#6, we discovered a resolution order that changed between the legacy and C3 orderings. This resolution order was created by directlyProvides(), not statically. For whatever reason, directlyProvides doesn't respect the environment variables that help debug changed resolution orders (ZOPE_INTERFACE_LOG_CHANGED_IRO and its superset ZOPE_INTERFACE_USE_LEGACY_IRO), so this had to be tracked down manually.

Can we make directlyProvides cheaply (!) respect those?

[jamadden]

It appears this is not actually true, at least not in all cases.

If we start Python and request logging of changed ROs, and create two interfaces to test with:

$ ZOPE_INTERFACE_LOG_CHANGED_IRO=1 python
Python 3.8.8 (default, Feb 27 2021, 05:51:16)
[Clang 12.0.0 (clang-1200.0.32.28)] on darwin
Type "help", "copyright", "credits" or "license" for more information.
>>> from zope.interface import Interface
>>> from zope.interface import implementer
>>> from zope.interface import directlyProvides
>>>
>>> class IBase(Interface):
...     pass
...
>>> class IDerived(IBase):
...     pass

We get the expected logging if we create a bad interface:

>>> class IDerivedBad(IBase, IDerived):
...     pass
...
Object <InterfaceClass __main__.IDerivedBad> had inconsistent IRO and used the legacy RO:
  Legacy RO (len=4)                            C3 RO (len=4; inconsistent=direct)
  ========================================================================================
    <InterfaceClass __main__.IDerivedBad>        <InterfaceClass __main__.IDerivedBad>
    <InterfaceClass __main__.IDerived>           <InterfaceClass __main__.IDerived>
    <InterfaceClass __main__.IBase>              <InterfaceClass __main__.IBase>
    <InterfaceClass zope.interface.Interface>    <InterfaceClass zope.interface.Interface>
Inconsistency entered at:
InconsistentResolutionOrderError: For object <InterfaceClass __main__.IDerivedBad>.
Base ROs:
{<InterfaceClass __main__.IBase>: [<InterfaceClass __main__.IBase>,
                                   <InterfaceClass zope.interface.Interface>],
 <InterfaceClass __main__.IDerived>: [<InterfaceClass __main__.IDerived>,
                                      <InterfaceClass __main__.IBase>,
                                      <InterfaceClass zope.interface.Interface>]}
Conflict Location:
[[<InterfaceClass __main__.IBase>, <InterfaceClass zope.interface.Interface>],
 [<InterfaceClass __main__.IDerived>,
  <InterfaceClass __main__.IBase>,
  <InterfaceClass zope.interface.Interface>],
 [<InterfaceClass __main__.IBase>, <InterfaceClass __main__.IDerived>]]

We get similar logging if we decorate a class with the bad order:

>>> @implementer(IBase, IDerived)
... class DerivedBad(object):
...     pass
...
Object <implementedBy __main__.DerivedBad> had inconsistent IRO and used the legacy RO:
  Legacy RO (len=5)                            C3 RO (len=5; inconsistent=direct)
  ========================================================================================
    <implementedBy __main__.DerivedBad>          <implementedBy __main__.DerivedBad>
    <InterfaceClass __main__.IDerived>           <InterfaceClass __main__.IDerived>
    <InterfaceClass __main__.IBase>              <InterfaceClass __main__.IBase>
    <InterfaceClass zope.interface.Interface>    <InterfaceClass zope.interface.Interface>
    <implementedBy builtins.object>              <implementedBy builtins.object>
Inconsistency entered at:
InconsistentResolutionOrderError: For object <implementedBy __main__.DerivedBad>.
Base ROs:
{<InterfaceClass __main__.IBase>: [<InterfaceClass __main__.IBase>,
                                   <InterfaceClass zope.interface.Interface>],
 <InterfaceClass __main__.IDerived>: [<InterfaceClass __main__.IDerived>,
                                      <InterfaceClass __main__.IBase>,
                                      <InterfaceClass zope.interface.Interface>],
 <implementedBy builtins.object>: [<implementedBy builtins.object>,
                                   <InterfaceClass zope.interface.Interface>]}
Conflict Location:
[[<InterfaceClass __main__.IBase>, <InterfaceClass zope.interface.Interface>],
 [<InterfaceClass __main__.IDerived>,
  <InterfaceClass __main__.IBase>,
  <InterfaceClass zope.interface.Interface>],
 [<implementedBy builtins.object>, <InterfaceClass zope.interface.Interface>],
 [<InterfaceClass __main__.IBase>,
  <InterfaceClass __main__.IDerived>,
  <implementedBy builtins.object>]]

If we create a class instance and directlyProvides the bad order, we also get the logging:

>>> class Plain(object):
...     pass
...
>>> ob = Plain()
>>> directlyProvides(ob, IBase, IDerived)
Object <zope.interface.Provides for <class '__main__.Plain'>> had inconsistent IRO and used the legacy RO:
  Legacy RO (len=6)                                         C3 RO (len=6; inconsistent=direct)
  ==================================================================================================================
    <zope.interface.Provides for <class '__main__.Plain'>>    <zope.interface.Provides for <class '__main__.Plain'>>
    <InterfaceClass __main__.IDerived>                        <InterfaceClass __main__.IDerived>
    <InterfaceClass __main__.IBase>                           <InterfaceClass __main__.IBase>
    <InterfaceClass zope.interface.Interface>                 <InterfaceClass zope.interface.Interface>
    <implementedBy __main__.Plain>                            <implementedBy __main__.Plain>
    <implementedBy builtins.object>                           <implementedBy builtins.object>
Inconsistency entered at:
InconsistentResolutionOrderError: For object <zope.interface.Provides for <class '__main__.Plain'>>.
Base ROs:
{<InterfaceClass __main__.IBase>: [<InterfaceClass __main__.IBase>,
                                   <InterfaceClass zope.interface.Interface>],
 <InterfaceClass __main__.IDerived>: [<InterfaceClass __main__.IDerived>,
                                      <InterfaceClass __main__.IBase>,
                                      <InterfaceClass zope.interface.Interface>],
 <implementedBy __main__.Plain>: [<implementedBy __main__.Plain>,
                                  <implementedBy builtins.object>,
                                  <InterfaceClass zope.interface.Interface>]}
Conflict Location:
[[<InterfaceClass __main__.IBase>, <InterfaceClass zope.interface.Interface>],
 [<InterfaceClass __main__.IDerived>,
  <InterfaceClass __main__.IBase>,
  <InterfaceClass zope.interface.Interface>],
 [<implementedBy __main__.Plain>,
  <implementedBy builtins.object>,
  <InterfaceClass zope.interface.Interface>],
 [<InterfaceClass __main__.IBase>,
  <InterfaceClass __main__.IDerived>,
  <implementedBy __main__.Plain>]]
None

(An indication of the location might be nice, but if you want that you can configure the logging subsystem to include it.)

All three also produce logging if we set ZOPE_INTERFACE_USE_LEGACY_IRO=1.

All three of those also produce errors if instead of ZOPE_INTERFACE_LOG_CHANGED_IRO=1 we use ZOPE_INTERFACE_STRICT_IRO=1 (but notably, not if you write ZOPE_INTERFACE_STRICT_IRO=1=1 python … as a result of a typo; the parsing of all these environment variables is quite strict and accepts only exactly '1' as the true value).

I'm still trying to replicate the issue from zopefoundation/zc.resourcelibrary#6.

[jamadden]

If I test the example from the referenced issue directly, where zope.site.folder.rootFolder() had an inconsistent IRO, and zope.site.folder.Folder had a changed IRO, with the current build of zope.interface and zope.site==4.3 (before the fix to the IROs in zope.site==4.5 in zopefoundation/zope.site#17), I get the expected output for ZOPE_INTERFACE_LOG_CHANGED_IRO=1 and ZOPE_INTERFACE_USE_LEGACY_IRO=1

$ ZOPE_INTERFACE_USE_LEGACY_IRO=1 python -c 'from zope.site.folder import rootFolder; rootFolder()'
...
Object <implementedBy zope.site.folder.Folder> has different legacy and C3 MROs:
  Legacy RO (len=25)                                                   C3 RO (len=25; inconsistent=no)
…
Object <zope.interface.Provides for <class 'zope.site.folder.Folder'>> had inconsistent IRO and used the legacy RO:
  Legacy RO (len=31)                                                   C3 RO (len=31; inconsistent=direct)
…
$ ZOPE_INTERFACE_LOG_CHANGED_IRO=1 python -c 'from zope.site.folder import rootFolder; rootFolder()'
...
Object <implementedBy zope.site.folder.Folder> has different legacy and C3 MROs:
  Legacy RO (len=25)                                                   C3 RO (len=25; inconsistent=no)
…
Object <zope.interface.Provides for <class 'zope.site.folder.Folder'>> has different legacy and C3 MROs:
  Legacy RO (len=31)                                                   C3 RO (len=31; inconsistent=no)
…

But interestingly, nothing is printed when asking for strict IRO:

$ ZOPE_INTERFACE_STRICT_IRO=1 python -c 'from zope.site.folder import rootFolder; rootFolder()'
$

The reason can be found in closely examining the output of the two previous cases. When we ask to use the legacy IRO, the directlyProvides(f, IRootFolder) tells us that it "had inconsistent IRO and used the legacy RO". But when we're using the C3 IRO, it just tells us that it "has different legacy and C3 MROs". There is no inconsistency (C3 was able to resolve the inconsistency), so there's nothing to warn about.

So perhaps what should be happening is that ZOPE_INTERFACE_STRICT_IRO should imply ZOPE_INTERFACE_LOG_CHANGED_IRO?