python: Modules/gcmodule.c:379: visit_decref: Assertion `((gc)->gc.gc_refs >> (1)) != 0' failed.

[vstinner]

BPO	20526
Nosy	@pitrou, @vstinner, @larryhastings, @ned-deily, @serhiy-storchaka
PRs	bpo-20526: Fix PyThreadState_Clear(): don't decref frame #19120 [3.8] bpo-20526: Fix PyThreadState_Clear(): don't decref frame (GH-19120) #19136 [3.7] bpo-20526: Fix PyThreadState_Clear(): don't decref frame (GH-19120) (GH-19136) #19137
Files	asyncio_gc.py threading_shutdown_interrupted.py revert_19466.patch

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = <Date 2020-03-24.16:58:23.930>
created_at = <Date 2014-02-06.09:14:02.239>
labels = ['interpreter-core', '3.7', '3.8', '3.9', 'type-crash']
title = "python: Modules/gcmodule.c:379: visit_decref: Assertion `((gc)->gc.gc_refs >> (1)) != 0' failed."
updated_at = <Date 2020-03-24.17:01:40.129>
user = 'https://github.com/vstinner'

bugs.python.org fields:

activity = <Date 2020-03-24.17:01:40.129>
actor = 'vstinner'
assignee = 'none'
closed = True
closed_date = <Date 2020-03-24.16:58:23.930>
closer = 'vstinner'
components = ['Interpreter Core']
creation = <Date 2014-02-06.09:14:02.239>
creator = 'vstinner'
dependencies = []
files = ['33939', '34053', '34056']
hgrepos = []
issue_num = 20526
keywords = ['patch']
message_count = 30.0
messages = ['210368', '210982', '210999', '211007', '211013', '211046', '211047', '211049', '211050', '211070', '211146', '211150', '211153', '213793', '214858', '214859', '214863', '214866', '214867', '214887', '214890', '214894', '364851', '364878', '364879', '364935', '364938', '364943', '364944', '364945']
nosy_count = 9.0
nosy_names = ['pitrou', 'vstinner', 'larry', 'ned.deily', 'Arfrever', 'neologix', 'python-dev', 'serhiy.storchaka', 'sebastien.renard']
pr_nums = ['19120', '19136', '19137']
priority = 'high'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'crash'
url = 'https://bugs.python.org/issue20526'
versions = ['Python 3.7', 'Python 3.8', 'Python 3.9']

[vstinner]

While trying to reproduce a race condition in asyncio, I got an assertion error from the Python garbage collector at exit. It's not easy to reproduce the issue: run attached script on Python 3.4 compiled in debug mode (to get assertions) and press CTRL+c twice. It looks like the bug occurs more often after at least 400 runs.

The Future class of the asyncio may store an exception in its private Future._exception attribute. An exception stores a traceback. I don't know if it's related.

Output:
---

...
run #347
^CTraceback (most recent call last):
  File "x.py", line 73, in <module>
    main()
  File "x.py", line 70, in main
    el.join()
  File "/home/haypo/prog/python/default/Lib/threading.py", line 1061, in join
    self._wait_for_tstate_lock()
  File "/home/haypo/prog/python/default/Lib/threading.py", line 1077, in _wait_for_tstate_lock
    elif lock.acquire(block, timeout):
run #348
KeyboardInterrupt
...
run #364
run #365
run #366
run #367
-cancelled-
run #368
^CException ignored in: <module 'threading' from '/home/haypo/prog/python/default/Lib/threading.py'>
Traceback (most recent call last):
  File "/home/haypo/prog/python/default/Lib/threading.py", line 1295, in _shutdown
    t.join()
  File "/home/haypo/prog/python/default/Lib/threading.py", line 1061, in join
    self._wait_for_tstate_lock()
  File "/home/haypo/prog/python/default/Lib/threading.py", line 1077, in _wait_for_tstate_lock
    elif lock.acquire(block, timeout):
KeyboardInterrupt
-cancelled-
python: Modules/gcmodule.c:379: visit_decref: Assertion `((gc)->gc.gc_refs >> (1)) != 0' failed.
Abandon (core dumped)

$ ls *core
python-6564.core

$ gdb ./python -c python-6564.core

Core was generated by `./python x.py'.
Program terminated with signal SIGABRT, Aborted.
(gdb) where
#0 0x0000003f3a835c59 in raise () from /lib64/libc.so.6
#1 0x0000003f3a837368 in abort () from /lib64/libc.so.6
#2 0x0000003f3a82ebb6 in __assert_fail_base () from /lib64/libc.so.6
#3 0x0000003f3a82ec62 in __assert_fail () from /lib64/libc.so.6
#4 0x000000000043ac66 in visit_decref (
op=Frame 0x7f013c001398, for file x.py, line 43, in task (self=<WorkerThread(_kwargs={}, loop=<_UnixSelectorEventLoop(_scheduled=[], _default_executor=None, _running=True, _ready=<collections.deque at remote 0x7f014bbed6e0>, _selector=<EpollSelector(_map=<_SelectorMapping(_selector=<...>) at remote 0x7f014c3bff60>, _epoll=<select.epoll at remote 0x7f014d5bce08>, _fd_to_key={5: <SelectorKey at remote 0x7f014bbecaf8>}) at remote 0x7f014c3bfae8>, _granularity=<float at remote 0x7f014e8c76b8>, _ssock=<socket at remote 0x7f014c3c5a78>, _internal_fds=1, _csock=<socket at remote 0x7f014bbeb5f8>, _signal_handlers={}) at remote 0x7f014c437400>, _is_stopped=False, _target=None, _daemonic=False, executor=<ThreadPoolExecutor(_max_workers=5, _shutdown=False, _work_queue=<Queue(not_empty=<Condition(release=<built-in method release of _thread.lock object at remote 0x7f014c3bb1a0>, acquire=<built-in method acquire of _thread.lock object at remote 0x7f014c3bb1a0>, _lock=<_thread.lock at remote 0x7f014c3bb1a0>, _waiters=<collecti...(truncated), data=0x0) at Modules/gcmodule.c:379
#5 0x00000000004336bd in tb_traverse (tb=0x7f01493a66e8, visit=0x43abb4 <visit_decref>, arg=0x0) at Python/traceback.c:64
#6 0x000000000043acdc in subtract_refs (containers=0x8f1a20 <generations+64>) at Modules/gcmodule.c:398
#7 0x000000000043bdee in collect (generation=2, n_collected=0x7fff499317c0, n_uncollectable=0x7fff499317b8, nofail=0)
at Modules/gcmodule.c:957
#8 0x000000000043c455 in collect_with_callback (generation=2) at Modules/gcmodule.c:1128
#9 0x000000000043d1d5 in PyGC_Collect () at Modules/gcmodule.c:1604
#10 0x000000000041e959 in Py_Finalize () at Python/pythonrun.c:605
#11 0x000000000043a890 in Py_Main (argc=2, argv=0x22bb020) at Modules/main.c:771
#12 0x000000000041aba9 in main (argc=2, argv=0x7fff49931ab8) at ./Modules/python.c:69

(gdb) frame 4
#4 0x000000000043ac66 in visit_decref (

(gdb) print op
$3 = Frame 0x7f013c001398, for file x.py, line 43, in task (self=<WorkerThread(_kwargs={}, loop=<_UnixSelectorEventLoop(_scheduled=[], _default_executor=None, _running=True, _ready=<collections.deque at remote 0x7f014bbed6e0>, _selector=<EpollSelector(_map=<_SelectorMapping(_selector=<...>) at remote 0x7f014c3bff60>, _epoll=<select.epoll at remote 0x7f014d5bce08>, _fd_to_key={5: <SelectorKey at remote 0x7f014bbecaf8>}) at remote 0x7f014c3bfae8>, _granularity=<float at remote 0x7f014e8c76b8>, _ssock=<socket at remote 0x7f014c3c5a78>, _internal_fds=1, _csock=<socket at remote 0x7f014bbeb5f8>, _signal_handlers={}) at remote 0x7f014c437400>, _is_stopped=False, _target=None, _daemonic=False, executor=<ThreadPoolExecutor(_max_workers=5, _shutdown=False, _work_queue=<Queue(not_empty=<Condition(release=<built-in method release of _thread.lock object at remote 0x7f014c3bb1a0>, acquire=<built-in method acquire of _thread.lock object at remote 0x7f014c3bb1a0>, _lock=<_thread.lock at remote 0x7f014c3bb1a0>, _waiters=<collecti...(truncated)
---

[vstinner]

At the first CTRL+c, the main thread exit and enters Py_Finalize() which calls wait_for_thread_shutdown() (in Python: threading._shutdown()).

The problem is that the second call interrupted threading._shutdown() (still in the main thread).

#9 0x000000000043d1d5 in PyGC_Collect () at Modules/gcmodule.c:1604
#10 0x000000000041e959 in Py_Finalize () at Python/pythonrun.c:605

At this point, we can expect that only one Python thread is running because wait_for_thread_shutdown() has been called, but there are between 2 and 9 running Python threads.

If wait_for_thread_shutdown() is interrupted, maybe Python should kill all other threads with pthread_kill() or something like that.

Or wait_for_thread_shutdown() should maybe block SIGINT and SIGTERM signals using pthread_sigmark()?

[pitrou]

If wait_for_thread_shutdown() is interrupted, maybe Python should kill > all other threads with pthread_kill() or something like that.

Or wait_for_thread_shutdown() should maybe block SIGINT and SIGTERM
signals using pthread_sigmark()?

This sounds a bit desperate.
Also, it doesn't explain why collecting the frame crashes. Does the refcount become inconsistent?

[neologix]

Random thoughts:

• executor-created threads are daemon (unfortunately)
• see issue bpo-19466: I think that the change to clear the frame of daemon
  threads was a mistake

[vstinner]

Random thoughts:

• executor-created threads are daemon (unfortunately)

Are you sure? I didn't see the daemon flag in ThreadPoolExecutor.

[vstinner]

Are you sure? I didn't see the daemon flag in ThreadPoolExecutor.

Oh you're right, ThreadPoolExecutor does create daemon threads:

class ThreadPoolExecutor(_base.Executor):
    ...

    def _adjust_thread_count(self):
        # When the executor gets lost, the weakref callback will wake up
        # the worker threads.
        def weakref_cb(_, q=self._work_queue):
            q.put(None)
        # TODO(bquinlan): Should avoid creating new threads if there are more
        # idle threads than items in the work queue.
        if len(self._threads) < self._max_workers:
            t = threading.Thread(target=_worker,
                                 args=(weakref.ref(self, weakref_cb),
                                       self._work_queue))
            t.daemon = True   <======= HERE
            t.start()
            self._threads.add(t)
            _threads_queues[t] = self._work_queue

[vstinner]

threading_shutdown_interrupted.py: simpler and reliable script to reproduce the bug.

[vstinner]

Charles-François wrote:

see issue bpo-19466: I think that the change to clear the frame of daemon
threads was a mistake

Good catch. If I reverted changes of bpo-19466, threading_shutdown_interrupted.py doesn't crash anymore.

It doesn't explain how the GC header of a frame object becomes inconsistent.

IMO fixing bpo-19466 was a good idea but because these changes, some bugs became more likley.

Maybe we can revert bpo-19466, then try to understand and fix this GC inconstency, and later fix again bpo-19466?

--

Oh by the way, threading_shutdown_interrupted.py shows also a deadlock. The main threads waits in threading._shutdown(), but this function is interrupted. Then it calls flush_std_files() which waits for a lock on stdout. The problem is that a thread was writing into stdout, but this thread is no more running and holds the lock.

[vstinner]

I set the priority to release blocker because it's a crash, it's a regression since Python 3.3 and it can be easily fixed (revert changes done in bpo-19466).

[vstinner]

revert_19466.patch: Patch to revert changes of issue bpo-19466. It restores how Python cleared threads in Python 3.3.

[neologix]

Please revert.

To debug, since I guess it's due to a memory corruption because objects are
deallocated while they're still in use, you could try to use valgrind.
Unfortunately, since it's due to a race condition, the overhead will
probably make it really hard to reproduce :-(

[python-dev]

New changeset 1166b3321012 by Victor Stinner in branch 'default':
Issue bpo-20526, bpo-19466: Revert changes of issue bpo-19466 which introduces a
http://hg.python.org/cpython/rev/1166b3321012

[vstinner]

To debug, since I guess it's due to a memory corruption because
objects are deallocated while they're still in use, you could try
to use valgrind.
Unfortunately, since it's due to a race condition, the overhead
will probably make it really hard to reproduce :-(

I added assert(_Py_Finalizing == NULL || _Py_Finalizing == PyThreadState_GET()) almost everywhere, but the assertion didn't fail. It looks like only the main thread is running between the interrupted wait_for_thread_shutdown() and the final "python: Modules/gcmodule.c:379: visit_decref: ... failed" assertion in PyGC_Collect().

I tried to add directly assert(_PyGCHead_REFS(gc) != 0) in _PyGCHead_SET_REFS(), but the assertion didn't fail.

I also ran Python in Valgrind: no error neither.

Ok...

I close this issue as won't fix because it was occur with bpo-19466 applied, but I just reverted this patch.