Diabolical bug involving code that behaves differently in a class decorator vs. a metaclass

bug.py

# bug.py

def decorate(func):
    print('Decorating', func.__name__)
    return func

def wrap_methods(cls):
    for name in vars(cls):
        if name.startswith('f_'):
            setattr(cls, name, decorate(getattr(cls, name)))
    return cls

class Meta(type):
    def __new__(meta, clsname, bases, methods):
        cls = super(Meta, meta).__new__(meta, clsname, bases, methods)
        wrap_methods(cls)
        return cls

print('---- Class Decorator ----')

@wrap_methods
class Spam1(object):
    def f_1(self): pass
    def f_2(self): pass
    def f_3(self): pass
    def f_4(self): pass
    def f_5(self): pass
    def f_6(self): pass
    def f_7(self): pass
    def f_8(self): pass

print('---- Metaclass ----')

class Spam2(metaclass=Meta):
    def f_1(self): pass
    def f_2(self): pass
    def f_3(self): pass
    def f_4(self): pass
    def f_5(self): pass
    def f_6(self): pass
    def f_7(self): pass
    def f_8(self): pass

output.txt

Runing the program, you get very different results for the two classes. The class decorator
version always does what's expected.  Not so much for the metaclass.

For example:

bash % python3 bug.py

---- Class Decorator ----
Decorating f_4
Decorating f_8
Decorating f_7
Decorating f_3
Decorating f_6
Decorating f_2
Decorating f_5
Decorating f_1
---- Metaclass ----    
Decorating f_4
Decorating f_3
Decorating f_5
Decorating f_2          # Notice: Where is f_7?  It's gone!
Decorating f_1
Decorating f_6
Decorating f_8

Try running it again:

---- Class Decorator ----
Decorating f_3
Decorating f_7
Decorating f_5
Decorating f_1
Decorating f_8
Decorating f_6
Decorating f_4
Decorating f_2
---- Metaclass ----
Decorating f_3       # <<<<<<
Decorating f_7
Decorating f_1
Decorating f_3       # WHAT?!?! This was just wrapped above
Decorating f_5
Decorating f_8
Decorating f_6
Decorating f_4
Decorating f_2

So yes, you're iterating over the class dictionary, changing the value assigned to some of the keys,
and effectively seeing the dictionary "change size", dropping one or more keys or iterating over
the same key more than once.  It randomly changes run-to-run.  Code behaves differently depending
if it's invoked from a metaclass or not.  

Enjoy!

Which version of Python 3 are you using? If I use 3.3.5, the bug stubbornly fails to reproduce. But if I use 3.4.1, it occurs within a handful of runs.

It may or may not be significant, but the order of "Decorating f_N" for the class and the metaclass always seems to be the same on 3.3.5; on 3.4.1, even when I don't see wonky output, the orders don't always match.

---

A little further prodding: if I print this hash inside the for loop:

 def wrap_methods(cls):
     for name in vars(cls):
+        print(' ' * 20 + hashlib.sha224(repr(vars(cls)).encode()).hexdigest())
         if name.startswith('f_'):
             setattr(cls, name, decorate(getattr(cls, name)))
     return cls

It stays the same within a class or metaclass run on 3.3.5. But on 3.4.1, it changes after the first "Decorating f_N" is printed. Further inspection shows that it's just the order of the keys changing; not the values. Why? I have no idea.

Yuck.

On newer versions of Python it can be made consistent between runs by using a fixed hash seed value:

$ PYTHONHASHSEED=1 python bug.py

see Python Docs

But that doesn't solve or explain the bug.

Tried with Python 3.5.1, and I can reproduce the bug.

Wraping vars(cls) with dict or list solves the problem. So maybe mappingproxy is in cause?

It's curious, types.MappingProxy was added in Python 3.3, but the bug only seems to show up in >= 3.4, not in 3.3.5. For Python < 3.3 (including 2.7), vars(cls) returns a DictProxy instead of MappingProxy (which I verified for 2.7, 3.0, 3.1, and 3.2, courtesy of python.net having all those versions installed). I thought maybe the behavior appeared with the introduction of MappingProxy, but in 3.3.5 there's no problem. It seems the behavior changed in 3.4 and 3.5.

The DictProxy -> types.MappingProxy change in 3.3 wasn't a change to the underlying implementation, just a matter of exposing the existing C implemented type to Python code.

While I haven't been able to reproduce the problem myself, https://twitter.com/caleb_hattingh/status/685097945788592132 suggests that the problem is the iteration order of C.__dict__ changing unexpectedly in a way the runtime doesn't detect. Wrapping the iteration in dict or list then avoids the problem, as it copies the original key order to a new container, unaffected by any order changes in the original namespace. (Note: the behaviour Caleb shows there is the same key ordering change that @alexwichan mentioned in the initial comment)

A simpler reproducer that looks specifically for the change in the order of the class namespace keys: https://bitbucket.org/ncoghlan/misc/src/default/tinkering/ns_reordering_bug.py

That will pretty consistently print "Broken = True" whether run via import or directly at the command line.

Switching to the commented out metaclass-as-callable implementation means it consistently prints "Broken = False", suggesting the problem lies somewhere in the use of a subclass of type as the metaclass rather than type itself, even though the subclass should be using the same tp_new implementation.

I (or more accurately, my laptop) am currently running hg bisect between 3.4.0rc2 and 3.4.1 against the reproducer script above (as it seems the regression appeared between those two tags). However, without a 100% reliable reproducer, bisect may not work.

bisect pins the blame on the patch for http://bugs.python.org/issue20637 at https://hg.python.org/cpython/rev/16229573e73e

One potential consequence of that patch: it means that instances of subclasses of type would have started to attempt to share keys with instances of type, whereas previously key sharing would have been implicitly disabled for all classes with a custom metaclass.