MTT pmix/libevent failure

[PeterGottesman]

Many MTT runs are failing with a SIGABRT. The example I will be using is https://mtt.open-mpi.org/index.php?do_redir=2642:

$ mpirun -np 32 --mca orte_startup_timeout 10000 --mca oob tcp --mca btl vader,tcp,self --mca btl_tcp_progress_thread 1 datatype/aint
[mpi006:14144] OPAL ERROR: Error in file pmix2x.c at line 326
<snip>

I am unable to reproduce the error, but have the coredump from the above run. The issue seems to be in the pmix2x event loop, but I am unsure of what event is failing.

(gdb) bt
#0  0x0000003f4bc32925 in raise () from /lib64/libc.so.6
#1  0x0000003f4bc34105 in abort () from /lib64/libc.so.6
#2  0x00002aaaab4edaf1 in opal_mutex_unlock (m=0x2aaaab9a5220 <mutex>) at ../../opal/threads/mutex_unix.h:155
#3  0x00002aaaab4eff1c in output (output_id=0, format=0x2aaaab718d80 "OPAL ERROR: %s in file %s at line %d", arglist=0x2aaaac3d8938) at output.c:1007
#4  0x00002aaaab4ee2fd in opal_output (output_id=0, format=0x2aaaab718d80 "OPAL ERROR: %s in file %s at line %d") at output.c:372
#5  0x00002aaaab5ae4f0 in pmix2x_event_hdlr (evhdlr_registration_id=3, status=-147, source=0x2aaab401dfec, info=0x2aaab401e150, ninfo=18446744073709551615, results=0x0, nresults=0,
    cbfunc=0x2aaaab646294 <progress_local_event_hdlr>, cbdata=0x2aaab401df10) at pmix2x.c:326
#6  0x00002aaaab6483b8 in pmix_invoke_local_event_hdlr (chain=0x2aaab401df10) at event/pmix_event_notification.c:770
#7  0x00002aaaab64f553 in check_cached_events (cd=0x6abb50) at event/pmix_event_registration.c:411
#8  0x00002aaaab64d82a in regevents_cbfunc (peer=0x690890, hdr=0x2aaab401dd80, buf=0x2aaaac3d8d00, cbdata=0x2aaab401db20) at event/pmix_event_registration.c:116
#9  0x00002aaaab6b2c16 in pmix_ptl_base_process_msg (fd=-1, flags=4, cbdata=0x2aaab401dca0) at base/ptl_base_sendrecv.c:711
#10 0x00002aaaab554fb3 in event_process_active_single_queue (base=0x690220, activeq=0x68dbf0) at event.c:1370
#11 0x00002aaaab555227 in event_process_active (base=0x690220) at event.c:1440
#12 0x00002aaaab55587a in opal_libevent2022_event_base_loop (base=0x690220, flags=1) at event.c:1644
#13 0x00002aaaab66a82b in progress_engine (obj=0x6901d8) at runtime/pmix_progress_threads.c:109
#14 0x0000003f4c0079d1 in start_thread () from /lib64/libpthread.so.0
#15 0x0000003f4bce8b6d in clone () from /lib64/libc.so.6
#16 0x0000000000000000 in ?? ()

I can also provide other information from the coredump on request.

[PeterGottesman]

This is a duplicate of #5309, however for organization's sake this is an issue instead of PR.

[PeterGottesman]

@rhc54 Hopefully this helps, I was able to get some of your debug output:

[mpi010:20489] VALUE UNLOAD NOT SUPPORTED FOR TYPE 12363
[mpi010:20489] OPAL ERROR: Error in file ../../../../../opal/mca/pmix/pmix2x/pmix2x.c at line 326
[mpi010:20489] VALUE UNLOAD NOT SUPPORTED FOR TYPE 55808
[mpi010:20489] OPAL ERROR: Error in file ../../../../../opal/mca/pmix/pmix2x/pmix2x.c at line 326
[mpi010:20489] VALUE UNLOAD NOT SUPPORTED FOR TYPE 55808
[mpi010:20489] OPAL ERROR: Error in file ../../../../../opal/mca/pmix/pmix2x/pmix2x.c at line 326

[rhc54]

Hmmm...those are just garbage. Is this happening in the daemon or in the app? Did something fail just before we hit this problem?

[PeterGottesman]

It doesn't seem to have anything new other than that.

Verify that this test is truly working because conncurrent MPI_Comm_spawns has not worked before.
Verify that this test is truly working because conncurrent MPI_Comm_spawns has not worked before.
level = 0
level = 0
Verify that this test is truly working because conncurrent MPI_Comm_spawns has not worked before.
Verify that this test is truly working because conncurrent MPI_Comm_spawns has not worked before.
Parent sent: level 0 (pid:27003)
level = 1
Verify that this test is truly working because conncurrent MPI_Comm_spawns has not worked before.
Parent sent: level 0 (pid:27002)
level = 1
Verify that this test is truly working because conncurrent MPI_Comm_spawns has not worked before.
Parent sent: level 1 (pid:27011)
level = 2
Parent sent: level 1 (pid:27010)
level = 2
Verify that this test is truly working because conncurrent MPI_Comm_spawns has not worked before.
Verify that this test is truly working because conncurrent MPI_Comm_spawns has not worked before.
Verify that this test is truly working because conncurrent MPI_Comm_spawns has not worked before.
Verify that this test is truly working because conncurrent MPI_Comm_spawns has not worked before.
Parent sent: level 2 (pid:27021)
level = 3
Verify that this test is truly working because conncurrent MPI_Comm_spawns has not worked before.
Parent sent: level 1 (pid:27010)
level = 2
Verify that this test is truly working because conncurrent MPI_Comm_spawns has not worked before.
Verify that this test is truly working because conncurrent MPI_Comm_spawns has not worked before.
Parent sent: level 2 (pid:27018)
level = 3
Parent sent: level 1 (pid:27011)
level = 2
Verify that this test is truly working because conncurrent MPI_Comm_spawns has not worked before.
Verify that this test is truly working because conncurrent MPI_Comm_spawns has not worked before.
Verify that this test is truly working because conncurrent MPI_Comm_spawns has not worked before.
[mpi022:27056] VALUE UNLOAD NOT SUPPORTED FOR TYPE 48877
[mpi022:27056] OPAL ERROR: Error in file ../../../../../opal/mca/pmix/pmix2x/pmix2x.c at line 326
[mpi022:27056] VALUE UNLOAD NOT SUPPORTED FOR TYPE 213
[mpi022:27056] OPAL ERROR: Error in file ../../../../../opal/mca/pmix/pmix2x/pmix2x.c at line 326
[mpi022:27056] VALUE UNLOAD NOT SUPPORTED FOR TYPE 213
[mpi022:27056] OPAL ERROR: Error in file ../../../../../opal/mca/pmix/pmix2x/pmix2x.c at line 326
[mpi022:27056] VALUE UNLOAD NOT SUPPORTED FOR TYPE 55808
[mpi022:27056] OPAL ERROR: Error in file ../../../../../opal/mca/pmix/pmix2x/pmix2x.c at line 326
[mpi022:27056] *** Process received signal ***
[mpi022:27056] Signal: Segmentation fault (11)
[mpi022:27056] Signal code: Invalid permissions (2)
[mpi022:27056] Failing at address: 0x2aaab4021048
[mpi022:27056] [ 0] /lib64/libpthread.so.0(+0xf710)[0x2aaaab272710]
[mpi022:27056] [ 1] /home/pgottesm/rompi/lib/libopen-pal.so.40(pmix2x_value_unload+0x1b)[0x2aaaabd824ff]
[mpi022:27056] [ 2] /home/pgottesm/rompi/lib/libopen-pal.so.40(pmix2x_event_hdlr+0x343)[0x2aaaabd81466]
[mpi022:27056] [ 3] /home/pgottesm/rompi/lib/libopen-pal.so.40(pmix_invoke_local_event_hdlr+0x9ac)[0x2aaaabe1c46f]
[mpi022:27056] [ 4] /home/pgottesm/rompi/lib/libopen-pal.so.40(+0x20f617)[0x2aaaabe23617]
[mpi022:27056] [ 5] /home/pgottesm/rompi/lib/libopen-pal.so.40(+0x20d8e2)[0x2aaaabe218e2]
[mpi022:27056] [ 6] /home/pgottesm/rompi/lib/libopen-pal.so.40(pmix_ptl_base_process_msg+0x309)[0x2aaaabe8703b]
[mpi022:27056] [ 7] /home/pgottesm/rompi/lib/libopen-pal.so.40(+0x113ce8)[0x2aaaabd27ce8]
[mpi022:27056] [ 8] /home/pgottesm/rompi/lib/libopen-pal.so.40(+0x113f5c)[0x2aaaabd27f5c]
[mpi022:27056] [ 9] /home/pgottesm/rompi/lib/libopen-pal.so.40(opal_libevent2022_event_base_loop+0x296)[0x2aaaabd285af]
[mpi022:27056] [10] /home/pgottesm/rompi/lib/libopen-pal.so.40(+0x22a947)[0x2aaaabe3e947]
[mpi022:27056] [11] /lib64/libpthread.so.0(+0x79d1)[0x2aaaab26a9d1]
[mpi022:27056] [12] /lib64/libc.so.6(clone+0x6d)[0x2aaaab568b6d]
[mpi022:27056] *** End of error message ***
-------------------------------------------------------
Child job 15 terminated normally, but 1 process returned
a non-zero exit code. Per user-direction, the job has been aborted.
-------------------------------------------------------
Parent sent: level 2 (pid:27028)
level = 3
Parent sent: level 2 (pid:27021)
level = 3
Parent sent: level 3 (pid:27027)
level = 4
Parent sent: level 3 (pid:27029)
level = 4
--------------------------------------------------------------------------
All nodes which are allocated for this job are already filled.
--------------------------------------------------------------------------
--------------------------------------------------------------------------
mpirun noticed that process rank 0 with PID 27056 on node mpi022 exited on signal 11 (Segmentation fault).
--------------------------------------------------------------------------
[savbu-usnic-a:25874] 4 more processes have sent help message help-orte-rmaps-base.txt / orte-rmaps-base:all-available-resources-used
[savbu-usnic-a:25874] Set MCA parameter "orte_base_help_aggregate" to 0 to see all help / error messages

[rhc54]

I see - so it is failing in the application process, and it repeatedly hits the error prior to crashing. Let me dig a bit - could be that the ORTE integration in that release isn't quite right or incomplete.

[PeterGottesman]

Okay, if it is any help at all, this is occurring in roughly 1% of runs of dynamic/no-disconnect for me. MTT seemed to have a slightly higher rate(2-3%), and considering it is the same machines you might have more luck reproducing the issue yourself with the machine under load.

Let me know what you find, I'm curious as to what is causing this.

[PeterGottesman]

I was able to reproduce a similar stack trace as openucx/ucx#2704, where there is a segfault in strdup, in the test info/00_create_cxx. I have been unable to reproduce this in the c version of the program, only the c++ version.

(gdb) bt
#0  0x0000003c12a81451 in __strlen_sse2 () from /lib64/libc.so.6
#1  0x0000003c12a81166 in strdup () from /lib64/libc.so.6
#2  0x00002aaaac61e9c0 in ?? ()
#3  0x00002aaab4020600 in ?? ()
#4  0x00002aaaac61da00 in ?? ()
#5  0x00002aaaab7eb2a7 in pmix2x_event_hdlr (evhdlr_registration_id=3, status=-147, source=0x2aaab401dfdc, info=0x2aaab401e140, ninfo=18446744073709551615, results=0x0, nresults=0,
    cbfunc=0x2aaaab887472 <progress_local_event_hdlr>, cbdata=0x2aaab401df00) at pmix2x.c:324
#6  0x00002aaaab889643 in pmix_invoke_local_event_hdlr (chain=0x2aaab401df00) at event/pmix_event_notification.c:770
#7  0x00002aaaab890da6 in check_cached_events (cd=0x6ba2d0) at event/pmix_event_registration.c:411
#8  0x00002aaaab88ef1c in regevents_cbfunc (peer=0x69efd0, hdr=0x2aaab401dd70, buf=0x2aaaac61dcb0, cbdata=0x2aaab401db10) at event/pmix_event_registration.c:116
#9  0x00002aaaab8f79e8 in pmix_ptl_base_process_msg (fd=-1, flags=4, cbdata=0x2aaab401dc90) at base/ptl_base_sendrecv.c:711
#10 0x00002aaaab790840 in event_process_active_single_queue (base=0x69e880, activeq=0x68a1f0) at event.c:1370
#11 0x00002aaaab790ab8 in event_process_active (base=0x69e880) at event.c:1440
#12 0x00002aaaab79110a in opal_libevent2022_event_base_loop (base=0x69e880, flags=1) at event.c:1644
#13 0x00002aaaab8ad0d0 in progress_engine (obj=0x69e838) at runtime/pmix_progress_threads.c:109
#14 0x0000003c12e079d1 in start_thread () from /lib64/libpthread.so.0
#15 0x0000003c12ae8b6d in clone () from /lib64/libc.so.6
#16 0x0000000000000000 in ?? ()

[jsquyres]

FWIW, ibm/info_create is a super short test (with no MPI communication, AFAIR). We've seen problems with super short tests before...? 🤷‍♂️

[rhc54]

@ggouaillardet Any chance you could take a look at this? I can't replicate using any of the tests that are reported as failing by MTT. It has to be some kind of memory corruption but I'm not immediately seeing it in the code.

[ggouaillardet]

@rhc54 I found an issue in the embedded PMIx of Open MPI v3.1.x

note I did not even try to understand why this scenario only occurs once in a while

In check_cached_events(), we

           /* all matches - notify */
            chain = PMIX_NEW(pmix_event_chain_t);
            // ...
            chain->ninfo = ncd->ninfo;
            PMIX_INFO_CREATE(chain->info, chain->ninfo);
            // ...
            pmix_invoke_local_event_hdlr(chain);

and then in pmix_invoke_local_event_hdlr(), we directly

  invk:
    /* start with the chain holding only the given info */
    chain->ninfo = chain->nallocated - 2;

chain->nallocated has never been updated, so its value is 0 as set in the constructor.
and then a memory corruption occurs because chain->ninfo < 0

The correct fix is likely to do things like (embedded PMIx from Open MPI) master

       /* create the chain */
        chain = PMIX_NEW(pmix_event_chain_t);
        // ...
        /* we always leave space for event hdlr name and a callback object */
        chain->nallocated = ncd->ninfo + 2;
        PMIX_INFO_CREATE(chain->info, chain->nallocated);
        // ...
        pmix_invoke_local_event_hdlr(chain);

[rhc54]

Oh my - ick! I would have thought that would be a problem every time as we always fire at least one notification (the programming model one) every time we invoke MPI. Guess it all depends on what memory gets "stomped".

Thanks for finding this! I'll fix it upstream (we'll need a new v2.1.x release) and create an OMPI PR.

[ggouaillardet]

Iirc, I set a breakpoint before the corruption can occurs, and do not hit it most of the time.