Issue #1928 resolved

Incorrect name lookup occurring in class defined inside of a function.

Graham Dumpleton
created an issue

Sorry, but I can't really supply a direct runnable test case that is going to trigger the bug, as the problem only manifests at some point after the JIT kicks in in some way. As such, it only triggers when run as part of a larger test suite we run under tox. At least that it relates to the JIT kicking in is all I can think of as to why when run in isolation there is no problem.

Anyway, the test program is shown below. I can't pair it back any further as when I start taking more out, even under our larger test suite it starts working okay, so is the minimal I can get such that still creates the problem. It needs pytest and wrapt to be installed.

import pytest
from wrapt import transient_function_wrapper

def override_application_name(name):
    class Application(object):
        @property
        def name(self):
            print('locals()', locals())
            print('type(name)', type(name))
            print('repr(name)', repr(name))
            print('type(Application.name)', type(Application.name))
            print('repr(Application.name)', repr(Application.name))
            return name

    @transient_function_wrapper(__name__, 'function_1')
    def _override_application_name(wrapped, instance, args, kwargs):
        def _bind_params(application, *args, **kwargs):
            return application, args, kwargs

        application, _args, _kwargs = _bind_params(*args, **kwargs)

        application = Application()

        return wrapped(application, *_args, **_kwargs)

    return _override_application_name

def function_1(obj):
    return obj

class Application(object):
    name = 'yyy'

@pytest.mark.parametrize(('a',), [(1,)])
def test_bug_many_3(a):
    @override_application_name('xxx')
    def test_bug():
        obj = function_1(Application())
        print('type(obj)', type(obj))
        print('obj.name', obj.name)
        assert isinstance(obj.name, str)
    test_bug()

So when run standalone using pypy 2.4.0, 2.2.1 and 1.9.0 this test works fine. But when run as part of a larger test suite under tox it fails.

The output we get is:

test_pypy_bug.py::test_bug_many_3[1] FAILED

======================================= FAILURES =======================================
__________________________________ test_bug_many_3[1] __________________________________

a = 1

    @pytest.mark.parametrize(('a',), [(1,)])
    def test_bug_many_3(a):
        @override_application_name('xxx')
        def test_bug():
            obj = function_1(Application())
            print('type(obj)', type(obj))
            print('obj.name', obj.name)
            assert isinstance(obj.name, str)
>       test_bug()

test_pypy_bug.py:42:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
.tox/pypy-without-extensions/site-packages/wrapt/wrappers.py:517: in __call__
    args, kwargs)
.tox/pypy-without-extensions/site-packages/wrapt/wrappers.py:800: in _execute
    return wrapped(*args, **kwargs)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

    @override_application_name('xxx')
    def test_bug():
        obj = function_1(Application())
        print('type(obj)', type(obj))
        print('obj.name', obj.name)
>       assert isinstance(obj.name, str)
E       assert isinstance(<property object at 0x000000010a232410>, str)
E        +  where <property object at 0x000000010a232410> = <test_pypy_bug.Application object at 0x000000010a207de0>.name

test_pypy_bug.py:41: AssertionError
--------------------------------- Captured stdout call ---------------------------------
('type(obj)', <class 'test_pypy_bug.Application'>)
('locals()', {'Application': <class 'test_pypy_bug.Application'>, 'self': <test_pypy_bug.Application object at 0x000000010a207de0>, 'name': <property object at 0x000000010a232410>})
('type(name)', <type 'property'>)
('repr(name)', '<property object at 0x000000010a232410>')
('type(Application.name)', <type 'property'>)
('repr(Application.name)', '<property object at 0x000000010a232410>')
('obj.name', <property object at 0x000000010a232410>)
('locals()', {'Application': <class 'test_pypy_bug.Application'>, 'self': <test_pypy_bug.Application object at 0x000000010a207de0>, 'name': <property object at 0x000000010a232410>})
('type(name)', <type 'property'>)
('repr(name)', '<property object at 0x000000010a232410>')
('type(Application.name)', <type 'property'>)
('repr(Application.name)', '<property object at 0x000000010a232410>')
============================== 1 failed in 19.40 seconds ===============================
ERROR: InvocationError: '/Users/graham/Work/python_agent/tests/agent_features/.tox/pypy-without-extensions/bin/py.test -v test_pypy_bug.py'
_______________________________________ summary ________________________________________
ERROR:   pypy-without-extensions: commands failed

For this code, when looking up the 'name' attribute from inside of the 'name' property method of the Application class which is nested inside of a function, it should be finding the 'name' argument of override_application_name().

As I said, this works fine as standalone test, but in larger test suite, the behaviour changes, and rather than return the 'name' argument of the outer function, it is using the 'name' property method. This is regardless of the fact that 'self' was not used and so it should not have been doing that.

I have added debug in so even if you can't manage to get it to trigger by filling the test file with lots of other code which is run first and so enables the JIT, that you can see that the lookup is wrong and so work from that.

The obvious workaround for this is not to use 'name' as the name of the outer function argument at the same time as calling the property method 'name'. So changing the outer argument to 'app_name' and making the return statement use that as well, then all works fine. Issue is only when the names for argument and property method are the same.

Comments (18)

  1. Armin Rigo

    Can't reproduce this. If possible, we would need to get the complete test case. We don't mind if it's a lot of code, requires installing more stuff, and so on. The difference between doing all this installation work and having nothing is the same as the difference between an annoying and a very hard problem (which would actually be impossible if we can't ask you questions that you can try out).

  2. Graham Dumpleton reporter

    It is a part of a proprietary test suite unfortunately. So would need to see if can toss out most stuff and still get it.

    Is there a way to disable the job besides giving the option explicitly to pypy? Can it be done by an environment variable?

    Since the problem arises in a py.test executed under tox I am having trouble finding where I can add the command line option. I actually tried to disable the jit when first found the issue but wasn't confident that what I was doing was disabling it.

    Otherwise, how can you tell whether it is disabled or not?

    The way I was trying to disable it was to modify the #! line of py.test itself to add the --jit off option at the end after pypy interpreter path given. It wasn't showing it as part of sys.argv though which from prior times I have used such a fiddle for other reasons, I thought it would show.

  3. Armin Rigo

    Actually you can turn off the JIT at any point:

    import pypyjit
    pypyjit.set_param("off")
    

    so you can put these for example at the very start of py.test itself.

    About sys.argv: it's normal that pypy --jit off x.py shows only sys.argv = ['x.py']; it's similar to how for example python -i x.py doesn't show the -i in sys.argv.

    Another thing to try: download a nightly build of pypy translated without any JIT, and with slightly different internal optimizations, from http://buildbot.pypy.org/nightly/trunk/ (e.g. pypy-c-nojit-latest-linux64.tar.bz2).

  4. Graham Dumpleton reporter

    Using pypyjit.set_param("off") in the conftest.py in the tox test directory doesn't cause it to go away, thus suggesting it isn't the JIT, but then also makes it more strange as to why it needs a large amount of code to have been loaded before the problem arises. I will keep trying to come up with a separate test which demonstrates it which doesn't depend on proprietary code.

  5. Armin Rigo

    Maybe the problem is not that name is looked up from the wrong place, but that the name argument of 'override_application_name()' has got its value overridden at some point by the name from the class body. Then we're looking at the wrong place by wondering why print(repr(name)) in the property body doesn't find nameas a string. To check if this is the case, try this:

    def override_application_name(name):
        def check_name():
            print 'override_application_name: name =', repr(name)
    
        class Application(object):
            @property
            def name(self):
                check_name()
                return name
    
  6. Graham Dumpleton reporter

    That does indeed look like it might be the case:

    def override_application_name(name):
        def check_name():
            print('override_application_name: name =', repr(name))
    
        class Application(object):
            @property
            def name(self):
                check_name()
                print('sys.argv', sys.argv)
                print('locals()', locals())
                print('type(name)', type(name))
                print('repr(name)', repr(name))
                print('type(Application.name)', type(Application.name))
                print('repr(Application.name)', repr(Application.name))
                return name
    

    This yields:

    ('type(obj)', <class 'test_pypy_bug.Application'>)
    ('override_application_name: name =', '<property object at 0x000000010575e020>')
    ('sys.argv', ['.tox/pypy-without-extensions/bin/py.test', '-v', 'test_pypy_bug.py'])
    ('locals()', {'check_name': <function check_name at 0x00000001046483e0>, 'Application': <class 'test_pypy_bug.Application'>, 'self': <test_pypy_bug.Application object at 0x000000010796b2b8>, 'name': <property object at 0x000000010575e020>})
    ('type(name)', <type 'property'>)
    ('repr(name)', '<property object at 0x000000010575e020>')
    ('type(Application.name)', <type 'property'>)
    ('repr(Application.name)', '<property object at 0x000000010575e020>')
    ('obj.name', <property object at 0x000000010575e020>)
    ('override_application_name: name =', '<property object at 0x000000010575e020>')
    ('sys.argv', ['.tox/pypy-without-extensions/bin/py.test', '-v', 'test_pypy_bug.py'])
    ('locals()', {'check_name': <function check_name at 0x00000001046483e0>, 'Application': <class 'test_pypy_bug.Application'>, 'self': <test_pypy_bug.Application object at 0x000000010796b2b8>, 'name': <property object at 0x000000010575e020>})
    ('type(name)', <type 'property'>)
    ('repr(name)', '<property object at 0x000000010575e020>')
    ('type(Application.name)', <type 'property'>)
    ('repr(Application.name)', '<property object at 0x000000010575e020>')
    
  7. Armin Rigo

    A possible hack to figure out where this name is changed:

    def override_application_name(name):
        def check_name(*args):
            assert type(name) is str
        sys.setprofile(check_name)
        ...
    
  8. Armin Rigo

    Ah, so it's early, around the class creation time. Then maybe you don't need the sys.setprofile() hack, and instead you can call check_name() manually at various points:

    def override_application_name(name):
        def check_name(*args):
            assert type(name) is str
        check_name()
    
        class Application(object):
            check_name()
            def name(self):
                check_name()
                return name
            check_name()
            name = property(name)
            check_name()
        check_name()
        ...
    
  9. Graham Dumpleton reporter

    This one is going to drive me mad. The location changes.

    Code is:

    import pytest
    import sys
    import traceback
    
    from wrapt import transient_function_wrapper
    
    def override_application_name(name): # 7
        def validate_name(*args): # 8
            if not isinstance(name, str):
                traceback.print_stack()
            assert type(name) is str
        #sys.setprofile(validate_name)
    
        def check_name():
            print('override_application_name: name =', repr(name))
    
        validate_name()
    
        class Application(object):
    
            validate_name()
    
            def name(self):
                validate_name()
                return name
    
            validate_name() # 27
    
            name = property(name)
    
            validate_name()
    
        validate_name()
    

    Most of the time when run this generates a traceback of:

      File "/Users/graham/Work/python_agent/tests/agent_features/test_pypy_bug.py", line 66, in test_bug_many_3
        @pytest.mark.parametrize(('a',), [(1,)])
      File "/Users/graham/Work/python_agent/tests/agent_features/test_pypy_bug.py", line 7, in override_application_name
        def override_application_name(name):
      File "/Users/graham/Work/python_agent/tests/agent_features/test_pypy_bug.py", line 8, in validate_name
        def validate_name(*args):
    

    which is particularly unhelpful.

    Occasionally, but not reproducible in any sane way I can work out, it produces:

      File "/Users/graham/Work/python_agent/tests/agent_features/test_pypy_bug.py", line 68, in test_bug_many_3
        @override_application_name('xxx')
      File "/Users/graham/Work/python_agent/tests/agent_features/test_pypy_bug.py", line 19, in override_application_name
        class Application(object):
      File "/Users/graham/Work/python_agent/tests/agent_features/test_pypy_bug.py", line 27, in Application
        validate_name()
      File "/Users/graham/Work/python_agent/tests/agent_features/test_pypy_bug.py", line 10, in validate_name
        traceback.print_stack()
    

    I tried removing the __pycache__ directory with the byte code files and changing the file after the byte code existed, but nothing was able to yield the latter. It just seemed random whether one would get the one where it pointed at line 27. Even getting it was hard as was quite rare.

    In the end I changed the test program such that it had sleep calls just prior to doing the checking.

    import pytest
    import sys
    import traceback
    import time
    
    from wrapt import transient_function_wrapper
    
    def override_application_name(name):
        def validate_name(*args):
            time.sleep(0.5)
            if not isinstance(name, str):
                traceback.print_stack()
            assert type(name) is str
    
        validate_name()
    
        class Application(object):
    
            validate_name()
    
            def name(self):
                validate_name()
                return name
    
            validate_name() # 25
    
            name = property(name)
    
            validate_name()
    
        validate_name()
    
        @transient_function_wrapper(__name__, 'function_1')
        def _override_application_name(wrapped, instance, args, kwargs):
            def _bind_params(application, *args, **kwargs):
                return application, args, kwargs
    
            application, _args, _kwargs = _bind_params(*args, **kwargs)
    
            application = Application()
    
            return wrapped(application, *_args, **_kwargs)
    
        return _override_application_name
    
    def function_1(obj):
        return obj
    
    class Application(object):
        name = 'yyy'
    
    @pytest.mark.parametrize(('a',), [(1,)])
    def test_bug_many_3(a):
        @override_application_name('xxx')
        def test_bug():
            obj = function_1(Application())
            assert isinstance(obj.name, str)
        test_bug()
    

    It would then reliably reproduce the problem at the same point, always pointing at:

      File "/Users/graham/Work/python_agent/tests/agent_features/test_pypy_bug.py", line 52, in test_bug_many_3
        @pytest.mark.parametrize(('a',), [(1,)])
      File "/Users/graham/Work/python_agent/tests/agent_features/test_pypy_bug.py", line 17, in override_application_name
        class Application(object):
      File "/Users/graham/Work/python_agent/tests/agent_features/test_pypy_bug.py", line 25, in Application
        validate_name() # 25
      File "/Users/graham/Work/python_agent/tests/agent_features/test_pypy_bug.py", line 12, in validate_name
        traceback.print_stack()
    

    Is pypy doing stuff in background threads????

    Our test suite has background threads running as well, but when I try and take this into a standalone test harness there isn't. Not sure if that is going to matter.

    Any other suggestions?

  10. Armin Rigo

    :-(

    The traceback you get most of the time doesn't make sense, btw. Is that really the traceback printed by traceback.print_stack()? Why doesn't it end in the line that contains traceback.print_stack()???

    No, PyPy doesn't run background threads. It makes no sense that time.sleep() should change anything, except if you have your own background threads that mess things up. But I don't see how it should be possible to mess up the class construction from a different thread...

  11. Graham Dumpleton reporter

    Yes, the traceback does in those cases really end with:

      File "/Users/graham/Work/python_agent/tests/agent_features/test_pypy_bug.py", line 52, in test_bug_many_3
        @pytest.mark.parametrize(('a',), [(1,)])
      File "/Users/graham/Work/python_agent/tests/agent_features/test_pypy_bug.py", line 8, in override_application_name
        def override_application_name(name):
      File "/Users/graham/Work/python_agent/tests/agent_features/test_pypy_bug.py", line 9, in validate_name
        def validate_name(*args):
    

    I couldn't make any sense either of why it was doing that.

    Time to sleep and ponder another day. Thanks for looking at it so far.

  12. Armin Rigo

    (In case it helps: I would be willing to debug it over ssh on your machines, with gdb over debug versions of pypy. Your company will have to trust me not to disclose your sources.)

  13. Armin Rigo

    Can you try removing all .pyc files around? In pytest, in your app, etc.

    If it doesn't help, try to reproduce on a different machine with a freshly downloaded pypy... (I'm unsure it would help because you report problems with multiple versions of pypy already.)

  14. Graham Dumpleton reporter

    Sorry, didn't see this last followup. Only found it while trying to get inbox back under control.

    Two of my colleagues were able to reproduce on their own laptops and our tests when run under tddium continuous integration service were also tripping it. That is why already knew affected multiple versions.

    Am trying to catch up with backlog, but will try the .pyc files when get a chance.

  15. Log in to comment