test_multiprocessing_spawn dumps core in AMD64 FreeBSD CURRENT Shared 3.x

[pablogsal]

BPO	36114
Nosy	@pitrou, @vstinner, @ambv, @ericsnowcurrently, @koobs, @pablogsal, @scotchka

^{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 2019-03-06.01:37:08.841>
created_at = <Date 2019-02-26.06:09:51.119>
labels = ['3.8', 'tests']
title = 'test_multiprocessing_spawn dumps core in AMD64 FreeBSD CURRENT Shared 3.x'
updated_at = <Date 2019-03-06.01:37:08.840>
user = 'https://github.com/pablogsal'

bugs.python.org fields:

activity = <Date 2019-03-06.01:37:08.840>
actor = 'vstinner'
assignee = 'none'
closed = True
closed_date = <Date 2019-03-06.01:37:08.841>
closer = 'vstinner'
components = ['Tests']
creation = <Date 2019-02-26.06:09:51.119>
creator = 'pablogsal'
dependencies = []
files = []
hgrepos = []
issue_num = 36114
keywords = []
message_count = 18.0
messages = ['336615', '336616', '337035', '337038', '337043', '337044', '337045', '337078', '337080', '337081', '337082', '337084', '337090', '337092', '337093', '337095', '337220', '337264']
nosy_count = 7.0
nosy_names = ['pitrou', 'vstinner', 'lukasz.langa', 'eric.snow', 'koobs', 'pablogsal', 'scotchka']
pr_nums = []
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = None
url = 'https://bugs.python.org/issue36114'
versions = ['Python 3.8']

[pablogsal]

OK (skipped=32)
Warning -- files was modified by test_multiprocessing_spawn
Before: []
After: ['python.core']

https://buildbot.python.org/all/#/builders/168/builds/632/steps/4/logs/stdio

[pablogsal]

Another failure:

https://buildbot.python.org/all/#/builders/168/builds/633

[scotchka]

Another example of this, same bot:

https://buildbot.python.org/all/#/builders/168/builds/669

[pablogsal]

After some investigation, this turns out to be more complicated, as this 'python.core' turns to be a core dumped from some of the processes spawned by test_multiprocessing_spawn. So the real problem is that test_multiprocessing_spawn segfaults, as in https://bugs.python.org/issue36116. I think this may be the same underlying problem. I will change the title to reflect this.

[pablogsal]

I managed to access the core file and this is the traceback:

Thread 3 (LWP 100629):
#0 0x00000008007d4828 in _accept4 () from /lib/libc.so.7
#1 0x0000000800672eda in ?? () from /lib/libthr.so.3
#2 0x00000008016f7b75 in ?? ()
#3 0x0000000800acca10 in ?? ()
#4 0x00007fffdfffcea0 in ?? ()
#5 0x00007fffdfffcea8 in ?? ()
#6 0x00007fffdfffce70 in ?? ()
#7 0x00007fffdfffce70 in ?? ()
#8 0x00000008025485a0 in ?? ()
#9 0x00007fffdfffcdf0 in ?? ()
#10 0x00000008016f820c in ?? ()
#11 0x00007fffdfffcdb0 in ?? ()
#12 0x0000000800384d02 in cfunction_call_varargs (func=0x8016ffb70, args=0x0, kwargs=<optimized out>) at Objects/call.c:770
#13 PyCFunction_Call (func=0x8016ffb70, args=0x0, kwargs=<optimized out>) at Objects/call.c:786
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

Thread 2 (LWP 101669):
#0 0x0000000801e0495d in CRYPTO_free () from /usr/local/lib/libcrypto.so.11
#1 0x0000000801de09bc in ?? () from /usr/local/lib/libcrypto.so.11
#2 0x0000000801e005b7 in OPENSSL_cleanup () from /usr/local/lib/libcrypto.so.11
#3 0x0000000800825ab1 in __cxa_finalize () from /lib/libc.so.7
#4 0x00000008007b2791 in exit () from /lib/libc.so.7
#5 0x00000008004ca84e in Py_Exit (sts=0) at Python/pylifecycle.c:2166
#6 0x00000008004d6ffb in handle_system_exit () at Python/pythonrun.c:641
#7 0x00000008004d6b07 in PyErr_PrintEx (set_sys_last_vars=1) at Python/pythonrun.c:651
#8 0x00000008004d698e in PyErr_Print () at Python/pythonrun.c:547
#9 PyRun_SimpleStringFlags (command=0x80150de38 "from multiprocessing.spawn import spawn_main; spawn_main(tracker_fd=4, pipe_handle=9)\n", flags=0x7fffffffe860) at Python/pythonrun.c:462
#10 0x00000008004f7a39 in pymain_run_command (command=<optimized out>, cf=0x0) at Modules/main.c:527
#11 pymain_run_python (interp=<optimized out>, exitcode=<optimized out>) at Modules/main.c:804
#12 pymain_main (args=<optimized out>) at Modules/main.c:896
#13 0x00000008004f84f7 in _Py_UnixMain (argc=<optimized out>, argv=0x801bdb848) at Modules/main.c:937
#14 0x0000000000201120 in _start (ap=<optimized out>, cleanup=<optimized out>) at /usr/src/lib/csu/amd64/crt1.c:76

Thread 1 (LWP 100922):
#0 0x000000080047ca84 in take_gil (tstate=0x80262ba10) at Python/ceval_gil.h:216
#1 0x000000080047d074 in PyEval_RestoreThread (tstate=0x80262ba10) at Python/ceval.c:281
#2 0x00000008004f3325 in _Py_write_impl (fd=5, buf=0x8025e3e00, count=29, gil_held=1) at Python/fileutils.c:1558
#3 0x00000008005051aa in os_write_impl (module=<optimized out>, fd=<optimized out>, data=<optimized out>) at ./Modules/posixmodule.c:8798
#4 os_write (module=<optimized out>, args=0x8015b3ba8, nargs=<optimized out>) at ./Modules/clinic/posixmodule.c.h:4182
#5 0x0000000800385a5d in _PyMethodDef_RawFastCallKeywords (method=<optimized out>, self=0x80127a5f0, args=<optimized out>, nargs=2, kwnames=<optimized out>) at Objects/call.c:653
#6 0x00000008003847de in _PyCFunction_FastCallKeywords (func=0x8012820c0, args=0x0, nargs=0, kwnames=0xdbdbdbdbdbdbdbdb) at Objects/call.c:732
#7 0x000000080048e1f5 in call_function (pp_stack=0x7fffdf7faf98, oparg=<optimized out>, kwnames=0x0) at Python/ceval.c:4673
#8 0x00000008004892fa in _PyEval_EvalFrameDefault (f=0x8015b3a00, throwflag=<optimized out>) at Python/ceval.c:3294
#9 0x000000080048f03a in PyEval_EvalFrameEx (f=<optimized out>, throwflag=<error reading variable: Cannot access memory at address 0x0>) at Python/ceval.c:624
#10 _PyEval_EvalCodeWithName (_co=<optimized out>, globals=<optimized out>, locals=<optimized out>, args=<optimized out>, argcount=2, kwnames=0x0, kwargs=0x8025e25f8, kwcount=0, kwstep=1, defs=0x802567798,
defcount=1, kwdefs=0x0, closure=0x0, name=0x8017e2930, qualname=0x80255b7c0) at Python/ceval.c:4035
#11 0x0000000800384690 in _PyFunction_FastCallKeywords (func=<optimized out>, stack=<optimized out>, nargs=0, kwnames=<optimized out>) at Objects/call.c:435
#12 0x000000080048e35f in call_function (pp_stack=0x7fffdf7fb2f0, oparg=<optimized out>, kwnames=0x0) at Python/ceval.c:4721

[pablogsal]

Apparently is the Thread 1 the one that is causing the core dump

[pablogsal]

This is the state of the thread interpreter:

gdb) p tstate
$3 = (PyThreadState *) 0x80262ba10
(gdb) p tstate->interp
$4 = (PyInterpreterState *) 0xdbdbdbdbdbdbdbdb

[vstinner]

I can reproduce the crash on my FreeBSD 12 VM:

vstinner@freebsd$ ./python -m test --fail-env-changed test_multiprocessing_spawn -v

FAIL: test_mymanager_context_prestarted (test.test_multiprocessing_spawn.WithManagerTestMyManager)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/usr/home/vstinner/prog/python/master/Lib/test/_test_multiprocessing.py", line 2754, in test_mymanager_context_prestarted
    self.assertEqual(manager._process.exitcode, 0)
AssertionError: -10 != 0

Warning -- files was modified by test_multiprocessing_spawn
Before: []
After: ['python.8184.core']

[pablogsal]

Interesting, I tried several hours to reproduce the crash on the buildbot itself manually and I could not do it.

[vstinner]

I recently (Feb 25) fixed the config of this slow buildbot to change the timeout from 15 min to 20 min:

python/buildmaster-config@37cf09c
python/buildmaster-config@e4155a7

It seems like there is a correlation between this buildbot config change and the buildbot starting to create a coredump file. The test started to create a core dump around build 624, Feb 25.

--

With coredump.

Warning -- files was modified by test_multiprocessing_spawn:

https://buildbot.python.org/all/#/builders/168/builds/624
# 625 was fine
https://buildbot.python.org/all/#/builders/168/builds/626
https://buildbot.python.org/all/#/builders/168/builds/628
https://buildbot.python.org/all/#/builders/168/builds/629
https://buildbot.python.org/all/#/builders/168/builds/630
https://buildbot.python.org/all/#/builders/168/builds/631

--

Without coredump: fail but no coredump.

ERROR: test_shared_memory_SharedMemoryManager_basics (test.test_multiprocessing_forkserver.WithProcessesTestSharedMemory)
ERROR: test_shared_memory_across_processes (test.test_multiprocessing_forkserver.WithProcessesTestSharedMemory)
ERROR: test_shared_memory_basics (test.test_multiprocessing_forkserver.WithProcessesTestSharedMemory)
ERROR: test_shared_memory_ShareableList_basics (test.test_multiprocessing_spawn.WithProcessesTestSharedMemory)
ERROR: test_shared_memory_ShareableList_pickling (test.test_multiprocessing_spawn.WithProcessesTestSharedMemory)
ERROR: test_shared_memory_SharedMemoryManager_basics (test.test_multiprocessing_spawn.WithProcessesTestSharedMemory)
ERROR: test_shared_memory_across_processes (test.test_multiprocessing_spawn.WithProcessesTestSharedMemory)
ERROR: test_shared_memory_basics (test.test_multiprocessing_spawn.WithProcessesTestSharedMemory)
ERROR: test_shared_memory_ShareableList_basics (test.test_multiprocessing_fork.WithProcessesTestSharedMemory)
ERROR: test_shared_memory_ShareableList_pickling (test.test_multiprocessing_fork.WithProcessesTestSharedMemory)
ERROR: test_shared_memory_SharedMemoryManager_basics (test.test_multiprocessing_fork.WithProcessesTestSharedMemory)
ERROR: test_shared_memory_across_processes (test.test_multiprocessing_fork.WithProcessesTestSharedMemory)
ERROR: test_shared_memory_basics (test.test_multiprocessing_fork.WithProcessesTestSharedMemory)
Re-running failed tests in verbose mode

https://buildbot.python.org/all/#/builders/168/builds/617
https://buildbot.python.org/all/#/builders/168/builds/618
https://buildbot.python.org/all/#/builders/168/builds/620
https://buildbot.python.org/all/#/builders/168/builds/622
https://buildbot.python.org/all/#/builders/168/builds/623

[vstinner]

I set the priority to release blocker to remind to fix this regression. I guess that it's the same bug than bpo-36116, but since it's a different OS (FreeBSD / Windows), I prefer to continue to use separated issues.