Odd issues related to Spawn.__del__

[luckyh]

For years I had seen a few odd issues, for instances:

08:29:49 DEBUG| [stderr] Exception 
08:29:49 DEBUG| [stderr] RuntimeError
08:29:49 DEBUG| [stderr] : 
08:29:49 DEBUG| [stderr] RuntimeError('cannot join current thread',)
08:29:49 DEBUG| [stderr]  in 
08:29:49 INFO | Running 'true'
08:29:49 DEBUG| [stderr] <module 'threading' from '/usr/lib64/python2.7/threading.pyc'>
08:29:49 DEBUG| [stderr]  ignored

22:17:31 DEBUG| [stderr] Exception ignored in: 
22:17:31 DEBUG| [stderr] <function Spawn.__del__ at 0x7f8be362eee0>
22:17:31 DEBUG| [stderr] 

22:17:31 DEBUG| [stderr] Traceback (most recent call last):

22:17:31 DEBUG| [stderr]   File "/usr/local/lib/python3.9/site-packages/aexpect-1.6.0-py3.9.egg/aexpect/client.py", line 229, in __del__

22:17:31 DEBUG| [stderr]     
22:17:31 DEBUG| [stderr] self.close()
22:17:31 DEBUG| [stderr] 

22:17:31 DEBUG| [stderr]   File "/usr/local/lib/python3.9/site-packages/aexpect-1.6.0-py3.9.egg/aexpect/client.py", line 365, in close

22:17:31 DEBUG| [stderr]     
22:17:31 DEBUG| [stderr] hook(self)
22:17:31 DEBUG| [stderr] 

22:17:31 DEBUG| [stderr]   File "/usr/local/lib/python3.9/site-packages/aexpect-1.6.0-py3.9.egg/aexpect/client.py", line 673, in _join_thread

22:17:31 DEBUG| [stderr]     
22:17:31 DEBUG| [stderr] thread = self.tail_thread
22:17:31 DEBUG| [stderr] 

22:17:31 DEBUG| [stderr] AttributeError
22:17:31 DEBUG| [stderr] : 
22:17:31 DEBUG| [stderr] 'RemoteSession' object has no attribute 'tail_thread'
22:17:31 DEBUG| [stderr] 

Recently I just took a look on that, and it turns out that the issues are related to Spawn.__del__ dealing with some conditions (e.g. sys.exit, handling signals ...). So here comes a question: can we provide a method to explicitly perform Spawn.__del__ instead, or is it possible to make __del__ bug free in our case?

Here is a simple reproducer to trigger the issues easier.
(Note: the worst case here is the program would be stuck at SystemExit: 0, but fortunately so far this rarely happens during test executions.)

import signal
import sys
import threading
import time

def bar():
    open(__file__, 'r').close()

def handler(n, s):
    sys.exit(0)

class Foo(object):

    def __init__(self):
        self.thread = threading.Thread(target=bar)

    def run(self):
        self.thread.start()

    def __del__(self):
        self.close()

    def close(self):
        self.thread.join()


if __name__ == '__main__':
    signal.signal(signal.SIGALRM, handler)
    signal.alarm(1)
    while True:
        f = Foo()
        f.run()

$ for i in {1..10}; do python2.7 r.py; done
Exception RuntimeError: RuntimeError('cannot join thread before it is started',) in <bound method Foo.__del__ of <__main__.Foo object at 0x7f782105bf10>> ignored
Exception AttributeError: "'Foo' object has no attribute 'thread'" in <bound method Foo.__del__ of <__main__.Foo object at 0x7fa57c99f250>> ignored
Exception AttributeError: "'Foo' object has no attribute 'thread'" in <bound method Foo.__del__ of <__main__.Foo object at 0x7f238a745f10>> ignored
Exception SystemExit: 0 in <bound method Foo.__del__ of <__main__.Foo object at 0x7f2a6aca3090>> ignored
...

$ for i in {1..10}; do python3.9 r.py; done
Exception ignored in: <function Foo.__del__ at 0x7efff607c280>
Traceback (most recent call last):
  File "/tmp/r.py", line 21, in __del__
    self.close()
  File "/tmp/r.py", line 24, in close
    self.thread.join()
AttributeError: 'Foo' object has no attribute 'thread'
Exception ignored in: <function Foo.__del__ at 0x7fed8e99a280>
Traceback (most recent call last):
  File "/tmp/r.py", line 21, in __del__
  File "/tmp/r.py", line 24, in close
  File "/usr/lib64/python3.9/threading.py", line 1028, in join
RuntimeError: cannot join thread before it is started
Exception ignored in: <function Foo.__del__ at 0x7f1895342280>
Traceback (most recent call last):
  File "/tmp/r.py", line 21, in __del__
    self.close()
  File "/tmp/r.py", line 24, in close
    self.thread.join()
  File "/usr/lib64/python3.9/threading.py", line 1033, in join
    self._wait_for_tstate_lock()
  File "/usr/lib64/python3.9/threading.py", line 1051, in _wait_for_tstate_lock
    self._stop()
  File "/usr/lib64/python3.9/threading.py", line 989, in _stop
    with _shutdown_locks_lock:
  File "/tmp/r.py", line 10, in exit
    sys.exit(0)
SystemExit: 0
...

[ldoktor]

Hello @luckyh, thank you for the analysis, I am seeing similar issues in my testing as well and it is annoying. Unfortunately I don't know how to treat this properly on the Aexpect side, maybe it'd be worth trying to raise this in the python community and ask for help there (either directly upstream or in RH BZ I bet there would be people that would be able to suggest a better approach). Can you please give it a try? With your reproducer it should be easy to grasp and it seems to basically explain the Aexpect usage.

As for workarounds, in Avocado-vt I am using timeout -s SIGINT $CTRL_C_TIMEOUT timeout $KILL_TIMEOUT avocado run ..., which seems to work well as it first tries to use ctrl+c and only in case of a complete hang forcefully interrupt the testing.

In other project I am using a tweak directly in the app which ensures properly killed background threads:

def handler(n, s):
    if len(threading.enumerate()) > 1:
        threads = threading.enumerate()
        if any("pydevd.Reader" in str(_) for _ in threads):
            logging.warning("Background threads %s present but 'pydev' "
                            "thread detected, not killing anything",
                            threads)
        else:
            log.warning("Background threads present, killing: %s",
                        threading.enumerate())
            os.kill(0, 15)
    sys.exit(0)

(The "pydev" tweak is there to not to crash Xorg in case this code is running inside Eclipse debugger)