master: TCP BTL addressing fail

[jsquyres]

Periodically, the Cisco MTT sees odd TCP BTL addressing failures.

For example, the one-sided TCP BTL failures from last night/s MTT on master (there's ORTE errors there, too -- ignore those): https://mtt.open-mpi.org/index.php?do_redir=2399

It looks like the TCP BTL fails the incoming connection, which then causes a frag mismatch size in OB1. Here's a stack trace:

Program terminated with signal SIGABRT, Aborted.
#0  0x0000003370632925 in raise () from /lib64/libc.so.6
[Current thread is 1 (Thread 0x2aaab959a700 (LWP 1394))]
(gdb) bt
#0  0x0000003370632925 in raise () from /lib64/libc.so.6
#1  0x0000003370634105 in abort () from /lib64/libc.so.6
#2  0x000000337062ba4e in __assert_fail_base () from /lib64/libc.so.6
#3  0x000000337062bb10 in __assert_fail () from /lib64/libc.so.6
#4  0x00002aaaaacdbaec in mca_pml_ob1_put_completion (frag=0x781380, 
    rdma_size=26666) at pml_ob1_recvreq.c:197
#5  0x00002aaaaacd80b6 in mca_pml_ob1_recv_frag_callback_fin (btl=0x6dd500, 
    tag=73 'I', des=0x2aaab9299080, cbdata=0x0) at pml_ob1_recvfrag.c:434
#6  0x00002aaaab4d0108 in mca_btl_tcp_endpoint_recv_handler (sd=24, flags=2, 
    user=0x739220) at btl_tcp_endpoint.c:893
#7  0x00002aaaab512393 in event_persist_closure (base=0x65c4e0, ev=0x739510)
    at event.c:1321
#8  0x00002aaaab5124a2 in event_process_active_single_queue (base=0x65c4e0, 
    activeq=0x65c9d0) at event.c:1365
#9  0x00002aaaab51276f in event_process_active (base=0x65c4e0) at event.c:1440
#10 0x00002aaaab512dc2 in opal_libevent2022_event_base_loop (base=0x65c4e0, 
    flags=1) at event.c:1644
#11 0x00002aaaab4cbe89 in mca_btl_tcp_progress_thread_engine (
    obj=0x2aaaab8fc1c0 <mca_btl_tcp_progress_thread>)
    at btl_tcp_component.c:781
#12 0x0000003370a079d1 in start_thread () from /lib64/libpthread.so.0
#13 0x00000033706e8b6d in clone () from /lib64/libc.so.6
#14 0x0000000000000000 in ?? ()
(gdb) 

The configuration of this run was:

"CFLAGS=-g -pipe" --enable-picky --enable-debug --enable-mpirun-prefix-by-default --enable-mpi-cxx --disable-dlopen --without-memory-manager

The corresponding output from the failed run was:

================ test_put6 ========== Sat Feb 25 03:08:56 2017
[mpi012:12152] btl: tcp: Incoming connection from 10.2.0.7 does not match known addresses for peer
[[28385,1],0]. Drop !
[mpi007:01397] btl: tcp: Incoming connection from 10.2.0.12 does not match known addresses for peer
[[28385,1],27]. Drop !
test_put6: pml_ob1_recvreq.c:197: mca_pml_ob1_put_completion: Assertion `(uint64_t) rdma_size ==
frag->rdma_length' failed.
[mpi007:01372] *** Process received signal ***
[mpi007:01372] Signal: Aborted (6)
[mpi007:01372] Signal code:  (-6)[mpi007:01372] [ 0] /lib64/libpthread.so.0[0x3370a0f710]
[mpi007:01372] [ 1] /lib64/libc.so.6(gsignal+0x35)[0x3370632925]
[mpi007:01372] [ 2] /lib64/libc.so.6(abort+0x175)[0x3370634105]
[mpi007:01372] [ 3] /lib64/libc.so.6[0x337062ba4e]
[mpi007:01372] [ 4] /lib64/libc.so.6(__assert_perror_fail+0x0)[0x337062bb10]
[mpi007:01372] [ 5]
/home/mpiteam/scratches/community/2017-02-24cron/KnEw/installs/iidk/install/lib/libmpi.so.0(+0x22eaec)[0x2aaaaacdbaec]
[mpi007:01372] [ 6]
/home/mpiteam/scratches/community/2017-02-24cron/KnEw/installs/iidk/install/lib/libmpi.so.0(mca_pml_ob1_recv_frag_callback_fin+0x74)[0x2aaaaacd80b6]
[mpi007:01372] [ 7]
/home/mpiteam/scratches/community/2017-02-24cron/KnEw/installs/iidk/install/lib/libopen-pal.so.0(+0xca108)[0x2aaaab4d0108]
[mpi007:01372] [ 8]
/home/mpiteam/scratches/community/2017-02-24cron/KnEw/installs/iidk/install/lib/libopen-pal.so.0(+0x10c393)[0x2aaaab512393]
[mpi007:01372] [ 9]
/home/mpiteam/scratches/community/2017-02-24cron/KnEw/installs/iidk/install/lib/libopen-pal.so.0(+0x10c4a2)[0x2aaaab5124a2]
[mpi007:01372] [10]
/home/mpiteam/scratches/community/2017-02-24cron/KnEw/installs/iidk/install/lib/libopen-pal.so.0(+0x10c76f)[0x2aaaab51276f]
[mpi007:01372] [11]
/home/mpiteam/scratches/community/2017-02-24cron/KnEw/installs/iidk/install/lib/libopen-pal.so.0(opal_libevent2022_event_base_loop+0x298)[0x2aaaab512dc2]
[mpi007:01372] [12]
/home/mpiteam/scratches/community/2017-02-24cron/KnEw/installs/iidk/install/lib/libopen-pal.so.0(+0xc5e89)[0x2aaaab4cbe89]
[mpi007:01372] [13] /lib64/libpthread.so.0[0x3370a079d1]
[mpi007:01372] [14] /lib64/libc.so.6(clone+0x6d)[0x33706e8b6d]
[mpi007:01372] *** End of error message ***-------------------------------------------------------
Primary job  terminated normally, but 1 process returned
a non-zero exit code. Per user-direction, the job has been aborted.
---------------------------------------------------------------------------------------------------------------------------------
An MPI communication peer process has unexpectedly disconnected.  This
usually indicates a failure in the peer process (e.g., a crash or
otherwise exiting without calling MPI_FINALIZE first).

Although this local MPI process will likely now behave unpredictably
(it may even hang or crash), the root cause of this problem is the
failure of the peer -- that is what you need to investigate.  For
example, there may be a core file that you can examine.  More
generally: such peer hangups are frequently caused by application bugs
or other external events.

  Local host: mpi012
  Local PID:  12152
  Peer host:  mpi007
----------------------------------------------------------------------------------------------------------------------------------------------------
mpirun noticed that process rank 0 with PID 0 on node mpi007 exited on signal 6 (Aborted).
--------------------------------------------------------------------------[mpi007:01352] 47 more
processes have sent help message help-mpi-btl-tcp.txt / peer hung up
[mpi007:01352] Set MCA parameter "orte_base_help_aggregate" to 0 to see all help / error messages

Note that 10.2.0.7 and 10.2.0.12 are valid IP addresses for MPI processes in this cluster, and actually correspond to the nodes that this SLURM MTT job was running on (mpi007 and mpi012). Here's an ifconfig from mpi002:

eth6      Link encap:Ethernet  HWaddr 24:57:20:02:50:00  
          inet addr:10.3.0.2  Bcast:10.3.255.255  Mask:255.255.0.0
          inet6 addr: fe80::2657:20ff:fe02:5000/64 Scope:Link
          UP BROADCAST RUNNING MULTICAST  MTU:9000  Metric:1
          RX packets:543911395 errors:0 dropped:2341 overruns:0 frame:0
          TX packets:558728146 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000 
          RX bytes:707847811000 (659.2 GiB)  TX bytes:779662168466 (726.1 GiB)

lo        Link encap:Local Loopback  
          inet addr:127.0.0.1  Mask:255.0.0.0
          inet6 addr: ::1/128 Scope:Host
          UP LOOPBACK RUNNING  MTU:16436  Metric:1
          RX packets:1198187857 errors:0 dropped:0 overruns:0 frame:0
          TX packets:1198187857 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:0 
          RX bytes:2382222734575 (2.1 TiB)  TX bytes:2382222734575 (2.1 TiB)

lom0      Link encap:Ethernet  HWaddr A4:4C:11:2A:72:68  
          inet addr:10.0.8.2  Bcast:10.0.255.255  Mask:255.255.0.0
          inet6 addr: fe80::a64c:11ff:fe2a:7268/64 Scope:Link
          UP BROADCAST RUNNING MULTICAST  MTU:1500  Metric:1
          RX packets:32785162 errors:0 dropped:0 overruns:0 frame:0
          TX packets:4297768 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000 
          RX bytes:7981061130 (7.4 GiB)  TX bytes:682224306 (650.6 MiB)
          Memory:cad00000-cae00000 

vic20     Link encap:Ethernet  HWaddr FC:99:47:25:2C:13  
          inet addr:10.10.0.2  Bcast:10.10.255.255  Mask:255.255.0.0
          inet6 addr: fe80::fe99:47ff:fe25:2c13/64 Scope:Link
          UP BROADCAST RUNNING MULTICAST  MTU:9000  Metric:1
          RX packets:595480496 errors:0 dropped:0 overruns:0 frame:0
          TX packets:628872360 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000 
          RX bytes:1160229624365 (1.0 TiB)  TX bytes:1379139113686 (1.2 TiB)

vic21     Link encap:Ethernet  HWaddr FC:99:47:25:2C:14  
          inet addr:10.2.0.2  Bcast:10.2.255.255  Mask:255.255.0.0
          inet6 addr: fe80::fe99:47ff:fe25:2c14/64 Scope:Link
          UP BROADCAST RUNNING MULTICAST  MTU:9000  Metric:1
          RX packets:508473520 errors:0 dropped:0 overruns:0 frame:0
          TX packets:528095836 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000 
          RX bytes:526753524743 (490.5 GiB)  TX bytes:607706247980 (565.9 GiB)

Hence, 10.2.0.7 and 10.2.0.21 should both be valid IP addresses for MPI processes in this job.

I'm a little confused by what is happening here at the abort point in the code, because it's in the case for CONNECTED, so it must be complaining about some other fragment -- not the "bad" inbound connection.

@bosilca Can you have a look?

[jsquyres]

@bosilca @rhc54 Is this open github issue related to the issue we discussed over this past weekend? This issue was reported quite a while ago -- before the current TCP verbosity about unknown peers -- so the output is different, and I can't easily tell if the stuff this past weekend was another symptom of this same issue.

Here's what I mailed @rhc54 and @bosilca this past weekend:

In (re)verifying that removing plm_base_verbose and leave-session-attached makes it work ok (on master, at least), I sometimes see this error when running the MTT trivial tests (e.g., 3-4 times out of ~20):

Running command: mpirun --mca odls_base_verbose 0 --mca plm_base_verbose 0 
  -np 32 --mca orte_startup_timeout 10000 --mca oob tcp --mca btl
  vader,tcp,self --mca btl_tcp_progress_thread 1 ./ring_mpifh 
Timeout: 15 - 1497786323 (vs. now: 1497786308)
--------------------------------------------------------------------------
  Open MPI detected an inbound MPI TCP connection request from a peer
  that appears to be part of this MPI job (i.e., it identified itself as
  part of this Open MPI job), but it is from an IP address that is
  unexpected.  This is highly unusual.

  The inbound connection has been dropped, and the peer should simply
  try again with a different IP interface (i.e., the job should
  hopefully be able to continue).

    Local host:          mpi002
    Local PID:           22680
    Peer hostname:       mpi001 ([[30163,1],10])
    Source IP of socket: 10.2.0.1
    Known IPs of peer:   
          0.0.0.0
-----------------------------------------------------------------------

Oddly, sometimes I see "Known IPs of peer: NONE" instead of "0.0.0.0".

This feels like the TCP BTL is not waiting for the modex information for a peer to arrive properly.

George: where does the TCP BTL wait for the modex info?

@bosilca replied:

Let me try to imagine a possible scenario (and hopefully the only one) that can lead to this output (and subsequent error).

But first, the difference between 0.0.0.0 and NONE is: when you see NONE that is because we don't know anything about the peer, not a single IP address despite the fact that the modex has been completed, when you see "0.0.0.0" we have extracted this IP from the modex (which is equally strange). So, in any case when we get here, the TCP BTL think that the modex has been successful (otherwise there will be other error messages).

Second, this message is generated in the callback for accept, so we are receiving a connection from a peer, we extract the guid from that connection, and the guid represent something in the job space. As this is [supposedly] the first connection from that peer, we need to build the local knowledge about the proc, so we do a blocking modex call (in mca_btl_tcp_proc_create in btl_tcp_proc.c). Keep in mind that we are in the callback from accept, so we are in one of the callbacks triggered by the event library, not necessarily the best place to execute a blocking call. So the question is should we assume that the blocking call in the libevent create issues or there is something more convoluted that is maybe outside the TCP BTL (and possible in the blocking modex interface) ?

Ralph, lets go over this code at the OMPI devel meeting.

@rhc54's reply:

Oh, am I glad you sent this, George! I can rig things inside the opal/pmix framework so that the blocking call while in an event isn’t a problem, now that I know someone needs to do so.

@bosilca's reply:

But the 2 are on different libevent eventsets. My understanding is that these should be totally independent, so I don't see how blocking on one can affect the other.

@rhc54's reply:

Yes, very true. However, we were about to inject a thread-shift in the OPAL pmix component itself as we are also touching framework-level globals there, and that would have occurred in the same event base (and therefore blocked). Not a big issue, but glad we caught it now so we can avoid the deadlock.

[bosilca]

I don't think these two issues are connected, because in order to be registered with the mca_btl_tcp_progress_thread_engine a peer need to successfully pass the connection step (which is what fails on the issue we were discussing this weekend).

[bosilca]

@jsquyres is this still happening on your environment ?

[jsquyres]

I do not believe so. Let's close this and re-open if it happens again.

[jsquyres]

Guess what? It's still happening in the Cisco MTT environment. 😦

Here's an MTT failed test where this problem occurred (on master on June 9, 2018). It's in a test that failed for another reason -- so you can ignore the shared memory / one-sided failure in that test.

But it implies that there is still a race condition in the TCP BTL: it seems like there's an inbound TCP BTL connection that arrives at process X before process X gets its modex information about the originating peer.

[jsquyres]

Still happening. Here's sample output:

--------------------------------------------------------------------------
Open MPI detected an inbound MPI TCP connection request from a peer
that appears to be part of this MPI job (i.e., it identified itself as
part of this Open MPI job), but it is from an IP address that is
unexpected.  This is highly unusual.

The inbound connection has been dropped, and the peer should simply
try again with a different IP interface (i.e., the job should
hopefully be able to continue).

  Local host:          mpi006
  Local PID:           26378
  Peer hostname:       (null) ([[18077,1],15])
  Source IP of socket: 10.2.0.5
  Known IPs of peer:
        0.0.0.0
—————————————————————————————————————

[bwbarrett]

@jsquyres does 10.2.0.5 seem like a sane address for this error message? The known IPs of peer thing being NULL is suspicious, but I have dim recollection that there was a bug in the printing, so I'm not sure whether or not that's the issue...

[jsquyres]

Yes, 10.2.0.5 is the IP address of one of the IP interfaces on this machine.

I have a dim recollection that this is a race condition -- the modex data hasn't arrived yet, so the "is this connection expected?" test fails.

[bosilca]

I am not sure I agree with your analysis. The TCP error you mention appears 4 times out of few hundreds errors on the MTT link provided, and as far as I can see in the traces it was never the cause of the segfault (I assume that as the shared memory issue appears on all tests it should be some temporary misconfiguration on the cluster).

Why this is not the real cause of an error is simple: we use multiple retries in the TCP BTL to cope with connection spamming issues. If a connection is dropped, the initiator assumes a temporal issue and will reconnect again. Thus, even if, due to lack of modex information, the first connection tentative was unsuccessful, follow-up connections will eventually succeed once the modex made the data available.

There might be an opportunity to exhaust all the retries and then completely give up connecting to a peer, but I do not see that type or error message on your output.

[jsquyres]

@bosilca FWIW: This is still happening in the Cisco MTT environment. E.g.: https://mtt.open-mpi.org/index.php?do_redir=2660

It's also happening in lots of tests that succeed: https://mtt.open-mpi.org/index.php?do_redir=2661

In all of those cases (failures and successes), we see this message:

--------------------------------------------------------------------------
Open MPI detected an inbound MPI TCP connection request from a peer
that appears to be part of this MPI job (i.e., it identified itself as
part of this Open MPI job), but it is from an IP address that is
unexpected.  This is highly unusual.

The inbound connection has been dropped, and the peer should simply
try again with a different IP interface (i.e., the job should
hopefully be able to continue).

  Local host:          mpi014
  Local PID:           7745
  Peer hostname:       (null) ([[14335,1],11])
  Source IP of socket: 10.2.0.13
  Known IPs of peer:   
	0.0.0.0
--------------------------------------------------------------------------

It really seems like a TCP BTL incorrectly rejected an inbound connection because it didn't have a full list of IP addresses of the peer.

Is the issue here that we're too aggressively displaying this show_help message? I.e., if it's going to retry, should we not show this message until it totally fail fail fails?

Perhaps in the failure MTT URL that I included above (https://mtt.open-mpi.org/index.php?do_redir=2660), the real errors are actually after that show_help message (i.e., an assertion failure and invalid data)...?