https://github.com/python/cpython/pull/28344/checks?check_run_id=3605759743
All tests pass until test_multiprocessing_fork timed out after 25 min.  On the rerun: refail with timeout.

test_get (test.test_multiprocessing_fork.WithProcessesTestQueue) ... Timeout (0:20:00)!
Thread 0x00007f176a71ebc0 (most recent call first):
  File "/home/runner/work/cpython/cpython/Lib/multiprocessing/synchronize.py", line 261 in wait
  File "/home/runner/work/cpython/cpython/Lib/multiprocessing/synchronize.py", line 349 in wait
  File "/home/runner/work/cpython/cpython/Lib/test/_test_multiprocessing.py", line 1001 in test_get
  File "/home/runner/work/cpython/cpython/Lib/unittest/case.py", line 549 in _callTestMethod
  File "/home/runner/work/cpython/cpython/Lib/unittest/case.py", line 593 in run
  File "/home/runner/work/cpython/cpython/Lib/unittest/case.py", line 652 in __call__
  File "/home/runner/work/cpython/cpython/Lib/unittest/suite.py", line 122 in run
  File "/home/runner/work/cpython/cpython/Lib/unittest/suite.py", line 84 in __call__
  File "/home/runner/work/cpython/cpython/Lib/unittest/suite.py", line 122 in run
  File "/home/runner/work/cpython/cpython/Lib/unittest/suite.py", line 84 in __call__
  File "/home/runner/work/cpython/cpython/Lib/unittest/suite.py", line 122 in run
  File "/home/runner/work/cpython/cpython/Lib/unittest/suite.py", line 84 in __call__
  File "/home/runner/work/cpython/cpython/Lib/unittest/runner.py", line 206 in run
  File "/home/runner/work/cpython/cpython/Lib/test/support/__init__.py", line 998 in _run_suite
  File "/home/runner/work/cpython/cpython/Lib/test/support/__init__.py", line 1124 in run_unittest
  File "/home/runner/work/cpython/cpython/Lib/test/libregrtest/runtest.py", line 261 in _test_module
  File "/home/runner/work/cpython/cpython/Lib/test/libregrtest/runtest.py", line 297 in _runtest_inner2
  File "/home/runner/work/cpython/cpython/Lib/test/libregrtest/runtest.py", line 340 in _runtest_inner
  File "/home/runner/work/cpython/cpython/Lib/test/libregrtest/runtest.py", line 215 in _runtest
  File "/home/runner/work/cpython/cpython/Lib/test/libregrtest/runtest.py", line 245 in runtest
  File "/home/runner/work/cpython/cpython/Lib/test/libregrtest/main.py", line 337 in rerun_failed_tests
  File "/home/runner/work/cpython/cpython/Lib/test/libregrtest/main.py", line 715 in _main
  File "/home/runner/work/cpython/cpython/Lib/test/libregrtest/main.py", line 658 in main
  File "/home/runner/work/cpython/cpython/Lib/test/libregrtest/main.py", line 736 in main
  File "/home/runner/work/cpython/cpython/Lib/test/__main__.py", line 2 in <module>
  File "/home/runner/work/cpython/cpython/Lib/runpy.py", line 86 in _run_code
  File "/home/runner/work/cpython/cpython/Lib/runpy.py", line 196 in _run_module_as_main

test_multiprocessing_fork also failed on the GitHub Action "Address sanitizer" job:
https://github.com/python/cpython/pull/28419

test_get (test.test_multiprocessing_fork.WithProcessesTestQueue) ... Timeout (0:20:00)!
Thread 0x00007f732679bbc0 (most recent call first):
  File "/home/runner/work/cpython/cpython/Lib/multiprocessing/synchronize.py", line 261 in wait
  File "/home/runner/work/cpython/cpython/Lib/multiprocessing/synchronize.py", line 349 in wait
  File "/home/runner/work/cpython/cpython/Lib/test/_test_multiprocessing.py", line 1001 in test_get

Sometimes, WithProcessesTestProcess.test_error_on_stdio_flush_1() hangs.

I'm able to reproduce the issue in a reliable way using attached bisect10 file and the command:

$ ./python -m test test_multiprocessing_fork --timeout=40 -v --matchfile=bisect10
(...)
test_fork (test.test_multiprocessing_fork.WithProcessesTestQueue) ... ok
test_get (test.test_multiprocessing_fork.WithProcessesTestQueue) ... 
Timeout (0:00:40)!
Thread 0x00007fd0552025c0 (most recent call first):
  File "/home/vstinner/python/main/Lib/multiprocessing/synchronize.py", line 261 in wait
  File "/home/vstinner/python/main/Lib/multiprocessing/synchronize.py", line 349 in wait
  File "/home/vstinner/python/main/Lib/test/_test_multiprocessing.py", line 1003 in test_get
(...)

bisect10 contains 68 tests.

> I'm able to reproduce the issue in a reliable way using attached bisect10 file and the command:

I'm talking about a Python built with Address Sanitizer:

$ ./configure --with-address-sanitizer --without-pymalloc
$ make

When the test hangs, a background Python process starts to use 100% of my CPU.

This process is stuck in _thread.start_new_thread(). I opened the process in gdb.

(gdb) thread 1
[Switching to thread 1 (Thread 0x7fece33615c0 (LWP 132301))]
#0  __interceptor_pthread_create (thread=thread@entry=0x7ffe79cd6190, attr=attr@entry=0x7ffe79cd61b0, start_routine=start_routine@entry=0x6fed30 <pythread_wrapper>, arg=arg@entry=0x60200019aed0)
    at ../../../../libsanitizer/asan/asan_interceptors.cpp:245
245	    while (atomic_load(&param.is_registered, memory_order_acquire) == 0)
(gdb) where
#0  __interceptor_pthread_create (thread=thread@entry=0x7ffe79cd6190, attr=attr@entry=0x7ffe79cd61b0, start_routine=start_routine@entry=0x6fed30 <pythread_wrapper>, arg=arg@entry=0x60200019aed0)
    at ../../../../libsanitizer/asan/asan_interceptors.cpp:245
#1  0x00000000006ff242 in PyThread_start_new_thread (func=func@entry=0x7f45d0 <thread_run>, arg=arg@entry=0x604000e83c50) at Python/thread_pthread.h:287
(...)

(gdb) thread 2
[Switching to thread 2 (Thread 0x7fecd151c640 (LWP 132302))]
#0  __sanitizer::atomic_exchange<__sanitizer::atomic_uint32_t> (mo=__sanitizer::memory_order_acquire, v=2, a=0x640000001b00) at ../../../../libsanitizer/sanitizer_common/sanitizer_atomic_clang.h:62
62	inline typename T::Type atomic_exchange(volatile T *a,
(gdb) where
#0  __sanitizer::atomic_exchange<__sanitizer::atomic_uint32_t> (mo=__sanitizer::memory_order_acquire, v=2, a=0x640000001b00) at ../../../../libsanitizer/sanitizer_common/sanitizer_atomic_clang.h:62
#1  __sanitizer::BlockingMutex::Lock (this=this@entry=0x640000001b00) at ../../../../libsanitizer/sanitizer_common/sanitizer_linux.cpp:649
#2  0x00007fece3914e15 in __sanitizer::GenericScopedLock<__sanitizer::BlockingMutex>::GenericScopedLock (mu=0x640000001b00, this=<synthetic pointer>) at ../../../../libsanitizer/sanitizer_common/sanitizer_mutex.h:183
#3  __sanitizer::SizeClassAllocator64<__asan::AP64<__sanitizer::LocalAddressSpaceView> >::GetFromAllocator (this=this@entry=0x7fece3a13f00 <__asan::instance>, stat=stat@entry=0x7feccfb46c40, class_id=class_id@entry=36, 
    chunks=chunks@entry=0x7feccfb42330, n_chunks=n_chunks@entry=8) at ../../../../libsanitizer/sanitizer_common/sanitizer_allocator_primary64.h:146
#4  0x00007fece3914f41 in __sanitizer::SizeClassAllocator64LocalCache<__sanitizer::SizeClassAllocator64<__asan::AP64<__sanitizer::LocalAddressSpaceView> > >::Refill (this=this@entry=0x7feccfb390e0, c=c@entry=0x7feccfb42320, 
    allocator=allocator@entry=0x7fece3a13f00 <__asan::instance>, class_id=class_id@entry=36) at ../../../../libsanitizer/sanitizer_common/sanitizer_allocator_local_cache.h:102
#5  0x00007fece3915209 in __sanitizer::SizeClassAllocator64LocalCache<__sanitizer::SizeClassAllocator64<__asan::AP64<__sanitizer::LocalAddressSpaceView> > >::Allocate (class_id=36, allocator=0x7fece3a13f00 <__asan::instance>, 
    this=0x7feccfb390e0) at ../../../../libsanitizer/sanitizer_common/sanitizer_allocator_local_cache.h:38
#6  __sanitizer::CombinedAllocator<__sanitizer::SizeClassAllocator64<__asan::AP64<__sanitizer::LocalAddressSpaceView> >, __sanitizer::LargeMmapAllocatorPtrArrayDynamic>::Allocate (this=this@entry=0x7fece3a13f00 <__asan::instance>, 
    cache=0x7feccfb390e0, size=<optimized out>, size@entry=8192, alignment=alignment@entry=1) at ../../../../libsanitizer/sanitizer_common/sanitizer_allocator_combined.h:69
#7  0x00007fece39118f6 in __asan::QuarantineCallback::Allocate (size=8192, this=<synthetic pointer>) at ../../../../libsanitizer/asan/asan_allocator.cpp:869
#8  __sanitizer::QuarantineCache<__asan::QuarantineCallback>::Enqueue (size=32, ptr=0x6030005477d0, cb=..., this=0x7feccfb39060) at ../../../../libsanitizer/sanitizer_common/sanitizer_quarantine.h:223
#9  __sanitizer::Quarantine<__asan::QuarantineCallback, __asan::AsanChunk>::Put (size=32, ptr=0x6030005477d0, cb=..., c=0x7feccfb39060, this=<optimized out>) at ../../../../libsanitizer/sanitizer_common/sanitizer_quarantine.h:105
#10 __asan::Allocator::QuarantineChunk (this=this@entry=0x7fece3a13f00 <__asan::instance>, m=m@entry=0x6030005477d0, stack=stack@entry=0x7fecd151b360, ptr=0x6030005477e0) at ../../../../libsanitizer/asan/asan_allocator.cpp:666
#11 0x00007fece3911ba5 in __asan::Allocator::Deallocate (alloc_type=__asan::FROM_MALLOC, stack=0x7fecd151b360, delete_alignment=0, delete_size=0, ptr=0x6030005477e0, this=0x7fece3a13f00 <__asan::instance>)
    at ../../../../libsanitizer/asan/asan_allocator.cpp:714
#12 0x00007fece3997618 in __interceptor_free (ptr=0x6030005477e0) at ../../../../libsanitizer/asan/asan_malloc_linux.cpp:128
#13 0x00007fece362f7a4 in pthread_getattr_np@GLIBC_2.2.5 () from /lib64/libc.so.6
#14 0x00007fece39b142e in __sanitizer::GetThreadStackTopAndBottom (at_initialization=at_initialization@entry=false, stack_top=stack_top@entry=0x7fecd151bd10, stack_bottom=stack_bottom@entry=0x7fecd151bd18)
    at ../../../../libsanitizer/sanitizer_common/sanitizer_linux_libcdep.cpp:143
#15 0x00007fece39b1778 in __sanitizer::GetThreadStackAndTls (main=<optimized out>, stk_addr=stk_addr@entry=0x7feccfb39020, stk_size=stk_size@entry=0x7fecd151bd68, tls_addr=tls_addr@entry=0x7feccfb39040, 
    tls_size=tls_size@entry=0x7fecd151bd60) at ../../../../libsanitizer/sanitizer_common/sanitizer_linux_libcdep.cpp:543
#16 0x00007fece39a3c93 in __asan::AsanThread::SetThreadStackAndTls (this=this@entry=0x7feccfb39000, options=<optimized out>) at ../../../../libsanitizer/asan/asan_thread.h:81
#17 0x00007fece39a3fd6 in __asan::AsanThread::Init (this=this@entry=0x7feccfb39000, options=options@entry=0x0) at ../../../../libsanitizer/asan/asan_thread.cpp:226
#18 0x00007fece39a446e in __asan::AsanThread::ThreadStart (this=0x7feccfb39000, os_id=132302, signal_thread_is_registered=0x7ffe79cd58f8) at ../../../../libsanitizer/asan/asan_thread.cpp:258
#19 0x00007fece3781299 in start_thread () from /lib64/libpthread.so.0
#20 0x00007fece36a9353 in clone () from /lib64/libc.so.6


The thread 1 is stuck at the loop at the end of pthread_create(), line 245 an 246: wait until &param.is_registered == 0.

210	INTERCEPTOR(int, pthread_create, void *thread,
211	    void *attr, void *(*start_routine)(void*), void *arg) {
212	  EnsureMainThreadIDIsCorrect();
213	  // Strict init-order checking is thread-hostile.
214	  if (flags()->strict_init_order)
215	    StopInitOrderChecking();
216	  GET_STACK_TRACE_THREAD;
217	  int detached = 0;
218	  if (attr)
219	    REAL(pthread_attr_getdetachstate)(attr, &detached);
220	  ThreadStartParam param;
221	  atomic_store(&param.t, 0, memory_order_relaxed);
222	  atomic_store(&param.is_registered, 0, memory_order_relaxed);
223	  int result;
224	  {
225	    // Ignore all allocations made by pthread_create: thread stack/TLS may be
226	    // stored by pthread for future reuse even after thread destruction, and
227	    // the linked list it's stored in doesn't even hold valid pointers to the
228	    // objects, the latter are calculated by obscure pointer arithmetic.
229	#if CAN_SANITIZE_LEAKS
230	    __lsan::ScopedInterceptorDisabler disabler;
231	#endif
232	    result = REAL(pthread_create)(thread, attr, asan_thread_start, &param);
233	  }
234	  if (result == 0) {
235	    u32 current_tid = GetCurrentTidOrInvalid();
236	    AsanThread *t =
237	        AsanThread::Create(start_routine, arg, current_tid, &stack, detached);
238	    atomic_store(&param.t, reinterpret_cast<uptr>(t), memory_order_release);
239	    // Wait until the AsanThread object is initialized and the ThreadRegistry
240	    // entry is in "started" state. One reason for this is that after this
241	    // interceptor exits, the child thread's stack may be the only thing holding
242	    // the |arg| pointer. This may cause LSan to report a leak if leak checking
243	    // happens at a point when the interceptor has already exited, but the stack
244	    // range for the child thread is not yet known.
245	    while (atomic_load(&param.is_registered, memory_order_acquire) == 0)
246	      internal_sched_yield();
247	  }
248	  return result;
249	}



The thread 2 seems to be stuck in a syscall done by __sanitizer::atomic_exchange<__sanitizer::atomic_uint32_t>, called by __sanitizer::BlockingMutex::Lock:

(gdb) disassemble 
Dump of assembler code for function _ZN11__sanitizer13BlockingMutex4LockEv:
   0x00007fece39af850 <+0>:	endbr64 
   0x00007fece39af854 <+4>:	push   r12
   0x00007fece39af856 <+6>:	push   rbp
   0x00007fece39af857 <+7>:	push   rbx
   0x00007fece39af858 <+8>:	mov    rcx,QWORD PTR [rdi+0x50]
   0x00007fece39af85c <+12>:	test   rcx,rcx
   0x00007fece39af85f <+15>:	jne    0x7fece39af8a8 <_ZN11__sanitizer13BlockingMutex4LockEv+88>
   0x00007fece39af861 <+17>:	mov    eax,0x1
   0x00007fece39af866 <+22>:	xchg   DWORD PTR [rdi],eax
   0x00007fece39af868 <+24>:	test   eax,eax
   0x00007fece39af86a <+26>:	je     0x7fece39af89e <_ZN11__sanitizer13BlockingMutex4LockEv+78>
   0x00007fece39af86c <+28>:	mov    ebp,0x2
   0x00007fece39af871 <+33>:	mov    r12d,0xca
   0x00007fece39af877 <+39>:	mov    esi,0x80
   0x00007fece39af87c <+44>:	xor    ebx,ebx
   0x00007fece39af87e <+46>:	mov    edx,0x2
   0x00007fece39af883 <+51>:	jmp    0x7fece39af896 <_ZN11__sanitizer13BlockingMutex4LockEv+70>
   0x00007fece39af885 <+53>:	nop    DWORD PTR [rax]
   0x00007fece39af888 <+56>:	mov    rax,r12
   0x00007fece39af88b <+59>:	mov    r10,rbx
   0x00007fece39af88e <+62>:	mov    r8,rbx
   0x00007fece39af891 <+65>:	mov    r9,rbx
   0x00007fece39af894 <+68>:	syscall 
=> 0x00007fece39af896 <+70>:	mov    eax,ebp
   0x00007fece39af898 <+72>:	xchg   DWORD PTR [rdi],eax
   0x00007fece39af89a <+74>:	test   eax,eax
   0x00007fece39af89c <+76>:	jne    0x7fece39af888 <_ZN11__sanitizer13BlockingMutex4LockEv+56>
   0x00007fece39af89e <+78>:	pop    rbx
   0x00007fece39af89f <+79>:	pop    rbp
   0x00007fece39af8a0 <+80>:	pop    r12
   0x00007fece39af8a2 <+82>:	ret    
   0x00007fece39af8a3 <+83>:	nop    DWORD PTR [rax+rax*1+0x0]
   0x00007fece39af8a8 <+88>:	xor    r8d,r8d
   0x00007fece39af8ab <+91>:	lea    rdx,[rip+0x37d7c]        # 0x7fece39e762e
   0x00007fece39af8b2 <+98>:	mov    esi,0x285
   0x00007fece39af8b7 <+103>:	lea    rdi,[rip+0x37dfa]        # 0x7fece39e76b8
   0x00007fece39af8be <+110>:	call   0x7fece39be990 <_ZN11__sanitizer11CheckFailedEPKciS1_yy>
End of assembler dump.

> https://github.com/python/cpython/pull/28344/checks?check_run_id=3605759743

That's an Address Sanitizer job.

Pablo: would it be possible to make the Address Sanitizer not mandatory on pull requests, until this libasan race condition is fixed?

> Pablo: would it be possible to make the Address Sanitizer not mandatory on pull requests, until this libasan race condition is fixed?

I don't think that's a good idea because then people will simply ignore it.

Pablo:
> I don't think that's a good idea because then people will simply ignore it.

On my PR 28419, I had to re-run the CI 2 or 3 times, it failed multiple times. It prevents to merge a PR whereas the failure is unrelated to the PR.

Terry was also affected on his IDLE's PR 28344.

I understand what you mean and I sympathize with it, but this is no different to random failures that we get in the other CI. 

The check is not failing constantly because otherwise no PRs could be merged and that's not what is happening.

I understand your points but my concerns remain: I don't think that's a good idea because then people will simply ignore it.

> I understand what you mean and I sympathize with it, but this is no different to random failures that we get in the other CI.

I'm fine with keeping a failing test if it's under our (Python) control. Here, it's a 3rd party issue. I cannot offer my help to fix libasan, but it will take time.

I didn't check the error rate of this issue. Usually, I'm not sure why, but I'm the one affected by every single test which fails randomly :-D

> I didn't check the error rate of this issue. Usually, I'm not sure why, but I'm the one affected by every single test which fails randomly :-D

If you wish, as a compromise we can ignore multiprocessing tests on ASAN build for now and leave them for the buildbots.

New changeset a356272362c15f2561872f3206baf5e9a0543997 by Pablo Galindo Salgado in branch 'main':
bpo-45200: Ignore test_multiprocessing_* in ASAN build due to false positives (GH-28492)
https://github.com/python/cpython/commit/a356272362c15f2561872f3206baf5e9a0543997

I reopen the issue: test_concurrent_futures seems to be also affected by this bug :-(

Example of recent hang:
https://github.com/python/cpython/runs/4908075699?check_suite_focus=true

---
0:18:04 load avg: 1.34 [417/418] test_peg_generator passed (9 min 46 sec) -- running: test_concurrent_futures (11 min 20 sec)
0:18:34 load avg: 0.81 running: test_concurrent_futures (11 min 50 sec)
0:19:04 load avg: 0.49 running: test_concurrent_futures (12 min 20 sec)
(...)
0:31:34 load avg: 0.00 running: test_concurrent_futures (24 min 50 sec)
Kill <TestWorkerProcess #3 running test=test_concurrent_futures pid=20092 time=25 min> process group
0:31:43 load avg: 0.00 [418/418/1] test_concurrent_futures timed out (25 min) (25 min)
(...)
0:31:43 load avg: 0.00 Re-running test_concurrent_futures in verbose mode
(...)

OK (skipped=6)

== Tests result: FAILURE then SUCCESS ==

409 tests OK.

10 slowest tests:
- test_concurrent_futures: 25 min
- test_peg_generator: 9 min 46 sec
- test_tools: 4 min 45 sec
- test_asyncio: 2 min 18 sec
- test_weakref: 1 min 26 sec
- test_venv: 1 min 24 sec
- test_subprocess: 1 min 6 sec
- test_lib2to3: 1 min 1 sec
- test_pickle: 59.4 sec
- test_gdb: 58.5 sec

9 tests skipped:
    test_devpoll test_ioctl test_kqueue test_msilib test_startfile
    test_winconsoleio test_winreg test_winsound test_zipfile64

1 re-run test:
    test_concurrent_futures
---

New changeset ce7d66771ec64488134a1dd114015aa056eef696 by Victor Stinner in branch 'main':
bpo-45200: GHA Address Sanitizer skips 3 slowest tests (GH-30797)
https://github.com/python/cpython/commit/ce7d66771ec64488134a1dd114015aa056eef696