Flux-core: python use after free on flux_rpc_t

[garlick]

I have a development branch which contains assertions on use-after-free in rpc.c. After rebasing on current master, which picks up the changes in pr #799, my assertions are triggering in the python tests.

First question is what to do with a core file generated by a python script. Hint appreciated?

$ ./t9990-python-tests.t
TAP version 13
#Running doctests and unit tests in: /home/garlick/proj/flux-core/src/bindings/python/test/event.py
ok 1 test.event.TestEvent.test_full_event
# {"test": "yay!"}
ok 2 test.event.TestEvent.test_t1_0_sub
ok 3 test.event.TestEvent.test_t1_1_unsub
#Running doctests and unit tests in: /home/garlick/proj/flux-core/src/bindings/python/test/wrapper.py
ok 4 test.wrapper.TestWrapper.test_automatic_unwrapping
ok 5 test.wrapper.TestWrapper.test_call_insufficient_arguments
ok 6 test.wrapper.TestWrapper.test_call_invalid_argument_type
ok 7 test.wrapper.TestWrapper.test_call_non_existant
ok 8 test.wrapper.TestWrapper.test_masked_function
ok 9 test.wrapper.TestWrapper.test_read_basic_value
python: rpc.c:75: flux_rpc_usecount_decr: Assertion `rpc->magic == RPC_MAGIC' failed.
./t9990-python-tests.t: line 8: 49583 Aborted                 (core dumped) ../src/bindings/python/test_commands/test_runner.t
$ gdb ../src/bindings/python/test_commands/test_runner.t ./core
[snip]
"/home/garlick/proj/flux-core/t/../src/bindings/python/test_commands/test_runner.t": not in executable format: File format not recognized
[New LWP 49108]
Core was generated by `python ../src/bindings/python/test_commands/test_runner.t'.
Program terminated with signal SIGABRT, Aborted.
#0  0x00007f71531be418 in ?? ()

Second question is any ideas what changed in the python bindings in #799 that might have introduced a use after free?

Should be able to reproduce by grabbing these two commits.

• 97cb0dee8f21ccd41454f24b9953c8ccc63a8233 adds the assertion checks
• a79aeb390c27a7ecb6101e0929fb2e3984d38865 fixes a use after free in the kvs which might trigger before you hit the above

[dongahn]

test_runner.t may not be an executable?

ASan could be used to analyze this. As is, however, if ASan detects other false positives like leaks before it gets to the error, it will stop proceeding. But you can at least build the code with --enable-sanitizer and run that particular test to see what sticks.

If that fails because of earlier false positives, I will see if I can suggest an alternative technique, which should be available with a later version of Clang. That should allow you to continue the analysis even after the initial errors.

[dongahn]

If you do file on the core, does it say what executable from which it was generated?

[garlick]

Thanks for those ideas - I'll follow up tomorrow.

Note in the gdb output, test_runner.t, a python script, is identified as the executable.

[dongahn]

Note in the gdb output, test_runner.t, a python script, is identified as the executable.

Ah... Yeah I had to guess that you will just have to override it with the actual python interpreter executable path... Even then, you may suffer dozens of stack frames that belong to the interpreter themselves. @lee218llnl found a way to filter out frames that belong to python for STAT but that probably only works when debug a live process.

[lee218llnl]

The Python source code includes a gdb script that you can use to do some rudimentary debugging at the Python level. Refer to https://docs.python.org/devguide/gdb.html for more info. What I do in STAT is based on this script.

[grondo]

@garlick, I'm sure @trws will chime in, but just wondering if before the rebase you were working on a branch with #807 applied? That seems more likely to be a source of this sort of thing than the constants rework (though admittedly I have zero knowledge here, so I probably go back to my corner)

[trws]

It's possible, 807 is where I would expect this to come from. I need to run some tests to see what's up exactly, but I haven't had use after free issues in 807 for several revisions. Maybe a file snuck in from an old version somehow, my sincere apologies if that's what's going on.

[springme]

Thanks for chiming in on the flux list, Greg.

From: Gregory Lee <[email protected][e-mail]>
Reply-To: flux-framework/flux-core <[email protected][e-mail]>
Date: Thursday, September 22, 2016 at 8:01 PM
To: flux-framework/flux-core <[email protected][e-mail]>
Subject: Re: [flux-framework/flux-core] python use after free on flux_rpc_t (#818)

The Python source code includes a gdb script that you can use to do some rudimentary debugging at the Python level. Refer to https://docs.python.org/devguide/gdb.html for more info. What I do in STAT is based on this script.

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHubhttps://github.com/flux-framework/flux-core/issues/818#issuecomment-249090240, or mute the threadhttps://github.com/notifications/unsubscribe-auth/AEdU0JTuymSymQ44VHsoblT8mUbq-KC7ks5qs0D3gaJpZM4KEfPk.

[garlick]

Oh right, I probably did not have 807 applied before and picked that up too.

[garlick]

I got a bit lost trying to pull in python-gdb.py but as I'm developing on a ubuntu system, it turns out that these instructions worked out and I was able to run python test_runner.t under gdb and get a python backtrace leading up to the assertion failure:

ok 9 test.wrapper.TestWrapper.test_read_basic_value
python: rpc.c:75: flux_rpc_usecount_decr: Assertion `rpc->magic == RPC_MAGIC' failed.

Program received signal SIGABRT, Aborted.
0x00007ffff7826418 in __GI_raise (sig=sig@entry=6)
    at ../sysdeps/unix/sysv/linux/raise.c:54
54  ../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
(gdb)  py-bt
Traceback (most recent call first):
  File "/home/garlick/proj/flux-core/src/bindings/python/flux/wrapper.py", line 175, in __call__
    result = self.fun(*args)
  File "/home/garlick/proj/flux-core/src/bindings/python/flux/wrapper.py", line 280, in __clear
    self.destructor(h)
  File "/home/garlick/proj/flux-core/src/bindings/python/flux/wrapper.py", line 296, in __del__
    self.__clear()
  File "/home/garlick/proj/flux-core/src/bindings/python/flux/wrapper.py", line 296, in __del__
    self.__clear()
  File "/usr/lib/python2.7/unittest/case.py", line 329, in run
    testMethod()
  File "/usr/lib/python2.7/unittest/case.py", line 393, in __call__
    return self.run(*args, **kwds)
  File "/usr/lib/python2.7/unittest/suite.py", line 108, in run
    test(result)
  File "/usr/lib/python2.7/unittest/suite.py", line 70, in __call__
    return self.run(*args, **kwds)
  File "/usr/lib/python2.7/unittest/suite.py", line 108, in run
    test(result)
  File "/usr/lib/python2.7/unittest/suite.py", line 70, in __call__
    return self.run(*args, **kwds)
  File "../src/bindings/python/test_commands/test_runner.t", line 19, in run_tests_with_size
    tests(result_set)
  File "../src/bindings/python/test_commands/test_runner.t", line 46, in run_under_dir
    run_tests_with_size(result_set, suite, size)
  File "../src/bindings/python/test_commands/test_runner.t", line 53, in <module>
    run_under_dir(result_set, '../test', 'test')

[trws]

I found the specific test that's causing issues, it's a wrapper test that's testing some functionality that nobody outside of the bindings should ever use (honestly I'm not sure anyone _in_ the bindings should either, but because it's possible there's a test for it). I'll figure out whats up ASAP, but for now commenting out "test_set_pimpl_handle" in wrapper.py should let everything pass.

[garlick]

Thanks @trws (and everybody!) - python tests are passing now.

[trws]

Ok, found the issue. The test was breaking because it was assigning the wrong kind of object into a handle slot, causing it to attempt to deallocate an invalid RPC object. I'm putting up a PR with the corrected test, checks in the assignment property method to prevent this in the future for all wrapped objects, and a new test that checks the assertions.