ucp_tag_send_nbx: Sender Successful but Receiver Fails to Detect Tag Data

[AVA022]

Hi! I am encountering an issue in my program where it seems that ucp_tag_send_nbx successfully sends data from the sender's side, but the receiver fails to detect the corresponding tag data (packet loss). I am not sure if this is a problem with the tag mode mechanism or if there might be an issue with my code logic.This issue cannot be reproduced consistently

• In other words, is the tag mode function reliable for data transmission?

Could anyone please provide some insights or suggestions on how to troubleshoot this issue?

[yosefe]

Hi, the tag mode, as all UCX APIs, is reliable. Can you pls provide the code (or some snippet) to demonstrate how tag API is used in your application?

[ivanallen]

I am encountering the same issue.

My server must handshake with the client to exchange the worker's address.

The client creates an endpoint to the server, then the server invokes ucp_tag_send_nbx and ucp_flush_nbx by the endpoint from the new come-in connection. The client invokes ucp_tag_recv_nbx on the ucp worker to get the server's work address.

If the client endpoint's error handler is invoked, the client will reconnect the server.

Everything is going well but the client didn't receive the tag message from the server when it restarted several counts. If I use TCP transport, this issue does not occur. It occurred occasionally using the SHM transport.

The server prints "send tag message OK" and "flush OK" but the client has not received any message.

It has the same issue if I replace TAG API with AM API.

@yosefe Could you please provide some suggestions ?

[ivanallen]

The client showed endpoints created ok but the am handler was not invoked.

client:

[2024-12-02 12:57:28.611] [info] [channel.cc:447] Reconnecting to server:10.16.43.32:8123 version:3
[1733115448.611215] [10-16-43-32:1687395:1]          ucp_ep.c:404  UCX  DEBUG created ep 0x7fce52e7b0a0 to 10.16.43.32:8123 from api call
[1733115448.611452] [10-16-43-32:1687395:1]            sock.c:344  UCX  DEBUG connect(fd=20, src_addr=10.16.43.32:52616 dest_addr=10.16.43.32:8123): Operation now in progress
[1733115448.611475] [10-16-43-32:1687395:1]           async.c:231  UCX  DEBUG added async handler 0x60600036d460 [id=20 ref 1] ???() to hash
[1733115448.611512] [10-16-43-32:1687395:1]           async.c:493  UCX  DEBUG listening to async event fd 20 events 0x2 mode thread_spinlock
[1733115448.611528] [10-16-43-32:1687395:1]   tcp_sockcm_ep.c:923  UCX  DEBUG created a TCP SOCKCM endpoint (fd=20) on tcp cm 0x61a000011a80, remote addr: 10.16.43.32:8123
[1733115448.611540] [10-16-43-32:1687395:1]   tcp_sockcm_ep.c:1126 UCX  DEBUG client created an endpoint on tcp_sockcm 0x61a000011a80 id: 20 state: 2
[1733115448.611553] [10-16-43-32:1687395:1]       wireup_ep.c:530  UCX  DEBUG ep 0x7fce52e7b0a0: wireup_ep 0x617000014280 set next_ep 0x60b00002bd80
[1733115448.611591] [10-16-43-32:1687395:1]           flush.c:381  UCX  DEBUG flush_nbx ep 0x7fce52e7b0a0
[1733115448.611600] [10-16-43-32:1687395:a]            sock.c:1043 UCX  DEBUG check ifname for socket on 10.16.43.32:0
[1733115448.612102] [10-16-43-32:1687395:a]            sock.c:1061 UCX  DEBUG matching ip found iface on ens4
[1733115448.612137] [10-16-43-32:1687395:a]       wireup_cm.c:608  UCX  DEBUG client created ep 0x7fce52e7b0a0 on device ens4, tl_bitmap 0x2 0x0 on cm rdmacm
[1733115448.612197] [10-16-43-32:1687395:1]           flush.c:381  UCX  DEBUG flush_worker ep 0x7fce52e7b0a0
[1733115448.612226] [10-16-43-32:1687395:1]       wireup_cm.c:184  UCX  DEBUG ep 0x7fce52e7b0a0: init_flags 0x36
[1733115448.612432] [10-16-43-32:1687395:1]         tcp_net.c:61   UCX  DEBUG speed of ens4 is UNKNOWN, assuming 100 Mbps
[1733115448.612585] [10-16-43-32:1687395:1]            topo.c:865  UCX  DEBUG /sys/class/net/ens4: PF sysfs path is '/sys/devices/pci0000:00/0000:00:04.0/virtio0'
[1733115448.612611] [10-16-43-32:1687395:1]             sys.c:433  UCX  DEBUG failed to open /sys/devices/pci0000:00/0000:00:04.0/virtio0/current_link_width: No such file or directory
[1733115448.612625] [10-16-43-32:1687395:1]             sys.c:1646 UCX  DEBUG ens4: could not read from '/sys/devices/pci0000:00/0000:00:04.0/virtio0/current_link_width'
[1733115448.612638] [10-16-43-32:1687395:1]            topo.c:818  UCX  DEBUG ens4: pci bandwidth undetected, using maximal value
[1733115448.612751] [10-16-43-32:1687395:1]         tcp_net.c:61   UCX  DEBUG speed of ens4 is UNKNOWN, assuming 100 Mbps
[1733115448.612857] [10-16-43-32:1687395:1]            topo.c:865  UCX  DEBUG /sys/class/net/ens4: PF sysfs path is '/sys/devices/pci0000:00/0000:00:04.0/virtio0'
[1733115448.612878] [10-16-43-32:1687395:1]             sys.c:433  UCX  DEBUG failed to open /sys/devices/pci0000:00/0000:00:04.0/virtio0/current_link_width: No such file or directory
[1733115448.612903] [10-16-43-32:1687395:1]             sys.c:1646 UCX  DEBUG ens4: could not read from '/sys/devices/pci0000:00/0000:00:04.0/virtio0/current_link_width'
[1733115448.612917] [10-16-43-32:1687395:1]            topo.c:818  UCX  DEBUG ens4: pci bandwidth undetected, using maximal value
[1733115448.613024] [10-16-43-32:1687395:1]          tcp_ep.c:259  UCX  DEBUG tcp_ep 0x60f000012010: created on iface 0x61c000006880, fd -1
[1733115448.613046] [10-16-43-32:1687395:1]       wireup_ep.c:489  UCX  DEBUG ep 0x7fce52e7b0a0: wireup_ep 0x617000014600 created next_ep 0x60f000012010 to 10.16.43.32:8123 using tcp/ens4
[1733115448.642255] [10-16-43-32:1687395:a]       wireup_cm.c:779  UCX  DEBUG ep 0x7fce52e7b0a0 flags 0xa04011 cfg_index 1: client connected status Success
[1733115448.642313] [10-16-43-32:1687395:1]       wireup_cm.c:658  UCX  DEBUG ep 0x7fce52e7b0a0 flags 0xa04011 cfg_index 1: client connect progress
[1733115448.642495] [10-16-43-32:1687395:1]         tcp_net.c:61   UCX  DEBUG     speed of ens4 is UNKNOWN, assuming 100 Mbps
[1733115448.642616] [10-16-43-32:1687395:1]            topo.c:865  UCX  DEBUG     /sys/class/net/ens4: PF sysfs path is '/sys/devices/pci0000:00/0000:00:04.0/virtio0'
[1733115448.642639] [10-16-43-32:1687395:1]             sys.c:433  UCX  DEBUG     failed to open /sys/devices/pci0000:00/0000:00:04.0/virtio0/current_link_width: No such file or directory
[1733115448.642656] [10-16-43-32:1687395:1]             sys.c:1646 UCX  DEBUG     ens4: could not read from '/sys/devices/pci0000:00/0000:00:04.0/virtio0/current_link_width'
[1733115448.642667] [10-16-43-32:1687395:1]            topo.c:818  UCX  DEBUG     ens4: pci bandwidth undetected, using maximal value
[1733115448.642746] [10-16-43-32:1687395:1]         tcp_net.c:61   UCX  DEBUG     speed of ens4 is UNKNOWN, assuming 100 Mbps
[1733115448.642839] [10-16-43-32:1687395:1]            topo.c:865  UCX  DEBUG     /sys/class/net/ens4: PF sysfs path is '/sys/devices/pci0000:00/0000:00:04.0/virtio0'
[1733115448.642859] [10-16-43-32:1687395:1]             sys.c:433  UCX  DEBUG     failed to open /sys/devices/pci0000:00/0000:00:04.0/virtio0/current_link_width: No such file or directory
[1733115448.642872] [10-16-43-32:1687395:1]             sys.c:1646 UCX  DEBUG     ens4: could not read from '/sys/devices/pci0000:00/0000:00:04.0/virtio0/current_link_width'
[1733115448.642883] [10-16-43-32:1687395:1]            topo.c:818  UCX  DEBUG     ens4: pci bandwidth undetected, using maximal value
[1733115448.642971] [10-16-43-32:1687395:1]          wireup.c:1214 UCX  DEBUG     ep 0x7fce52e7b0a0: am_lane 1 wireup_msg_lane 1 cm_lane 0 keepalive_lane <none> reachable_mds 0x4
[1733115448.642989] [10-16-43-32:1687395:1]          wireup.c:1237 UCX  DEBUG     ep 0x7fce52e7b0a0: lane[0]: cm rdmacm
[1733115448.643006] [10-16-43-32:1687395:1]          wireup.c:1237 UCX  DEBUG     ep 0x7fce52e7b0a0: lane[1]:  1:tcp/ens4.0 md[1]              -> addr[0].md[2]/tcp/sysdev[255] seg 4294967295 rma_bw#0 am am_bw#0 wireup
[1733115448.643018] [10-16-43-32:1687395:1]          wireup.c:1240 UCX  DEBUG     ep 0x7fce52e7b0a0: err mode 1, flags 0x6
[1733115448.643039] [10-16-43-32:1687395:1]          tcp_cm.c:96   UCX  DEBUG     tcp_ep 0x60f000012010: CLOSED -> CONNECTING for the [10.16.43.32:34347]<->[10.16.43.32:40313]:3 connection [-:Rx]
[1733115448.643067] [10-16-43-32:1687395:1]          tcp_cm.c:96   UCX  DEBUG     tcp_ep 0x60f000012010: CONNECTING -> CONNECTING for the [10.16.43.32:34347]<->[10.16.43.32:40313]:3 connection [-:Rx]
[1733115448.643231] [10-16-43-32:1687395:1]            sock.c:344  UCX  DEBUG     connect(fd=22, src_addr=10.16.43.32:59204 dest_addr=10.16.43.32:40313): Success
[1733115448.643271] [10-16-43-32:1687395:1]          tcp_cm.c:96   UCX  DEBUG     tcp_ep 0x60f000012010: CONNECTING -> CONNECTED for the [10.16.43.32:34347]<->[10.16.43.32:40313]:3 connection [-:Rx]
[1733115448.643960] [10-16-43-32:1687395:1]         tcp_net.c:61   UCX  DEBUG   speed of ens4 is UNKNOWN, assuming 100 Mbps
[1733115448.644078] [10-16-43-32:1687395:1]            topo.c:865  UCX  DEBUG   /sys/class/net/ens4: PF sysfs path is '/sys/devices/pci0000:00/0000:00:04.0/virtio0'
[1733115448.644101] [10-16-43-32:1687395:1]             sys.c:433  UCX  DEBUG   failed to open /sys/devices/pci0000:00/0000:00:04.0/virtio0/current_link_width: No such file or directory
[1733115448.644118] [10-16-43-32:1687395:1]             sys.c:1646 UCX  DEBUG   ens4: could not read from '/sys/devices/pci0000:00/0000:00:04.0/virtio0/current_link_width'
[1733115448.644128] [10-16-43-32:1687395:1]            topo.c:818  UCX  DEBUG   ens4: pci bandwidth undetected, using maximal value
[1733115448.644211] [10-16-43-32:1687395:1]            sock.c:90   UCX  DEBUG   ioctl(req=35142, ifr_name=lo) failed: Operation not supported
[1733115448.644235] [10-16-43-32:1687395:1]         tcp_net.c:61   UCX  DEBUG   speed of lo is UNKNOWN, assuming 100 Mbps
[1733115448.644334] [10-16-43-32:1687395:1]            topo.c:861  UCX  DEBUG   /sys/class/net/lo: sysfs path undetected
[1733115448.644355] [10-16-43-32:1687395:1]            topo.c:818  UCX  DEBUG   lo: pci bandwidth undetected, using maximal value
[1733115448.644461] [10-16-43-32:1687395:1]          wireup.c:1214 UCX  DEBUG   ep 0x7fce52e7b0a0: am_lane 1 wireup_msg_lane 4 cm_lane 0 keepalive_lane 1 reachable_mds 0x1d
[1733115448.644478] [10-16-43-32:1687395:1]          wireup.c:1237 UCX  DEBUG   ep 0x7fce52e7b0a0: lane[0]: cm rdmacm
[1733115448.644489] [10-16-43-32:1687395:1]          wireup.c:1237 UCX  DEBUG   ep 0x7fce52e7b0a0: lane[1]:  3:sysv/memory.0 md[2]           -> addr[4].md[3]/sysv/sysdev[255] seg 4294967295 am am_bw#0 keepalive
[1733115448.644504] [10-16-43-32:1687395:1]          wireup.c:1237 UCX  DEBUG   ep 0x7fce52e7b0a0: lane[2]:  4:posix/memory.0 md[3]          -> addr[5].md[4]/posix/sysdev[255] seg 4294967295
[1733115448.644519] [10-16-43-32:1687395:1]          wireup.c:1237 UCX  DEBUG   ep 0x7fce52e7b0a0: lane[3]:  2:tcp/lo.0 md[1]                -> addr[3].md[2]/tcp/sysdev[255] seg 4294967295 rma_bw#0
[1733115448.644533] [10-16-43-32:1687395:1]          wireup.c:1237 UCX  DEBUG   ep 0x7fce52e7b0a0: lane[4]:  1:tcp/ens4.0 md[1]              -> addr[2].md[2]/tcp/sysdev[255] seg 4294967295 rma_bw#1 wireup
[1733115448.644544] [10-16-43-32:1687395:1]          wireup.c:1240 UCX  DEBUG   ep 0x7fce52e7b0a0: err mode 1, flags 0x2
[1733115448.644582] [10-16-43-32:1687395:1]           mm_ep.c:69   UCX  DEBUG   mm_ep 0x60e000060520: attached remote segment id 0xa18025 at 0x7fce52e00000 cookie 0xbebebebebebebebe
[1733115448.644635] [10-16-43-32:1687395:1]           mm_ep.c:203  UCX  DEBUG   created mm ep 0x60e000060520, connected to remote FIFO id 0xa18025
[1733115448.644655] [10-16-43-32:1687395:1]       wireup_ep.c:530  UCX  DEBUG   ep 0x7fce52e7b0a0: wireup_ep 0x617000014980 set next_ep 0x60e000060520
[1733115448.644682] [10-16-43-32:1687395:1]           mm_ep.c:69   UCX  DEBUG   mm_ep 0x60e000060600: attached remote segment id 0xc00000034019bf87 at 0x7fce31c01000 cookie 0x80ff
[1733115448.644712] [10-16-43-32:1687395:1]           mm_ep.c:203  UCX  DEBUG   created mm ep 0x60e000060600, connected to remote FIFO id 0xc00000034019bf87
[1733115448.644726] [10-16-43-32:1687395:1]       wireup_ep.c:530  UCX  DEBUG   ep 0x7fce52e7b0a0: wireup_ep 0x617000014d00 set next_ep 0x60e000060600
[1733115448.644754] [10-16-43-32:1687395:1]          tcp_ep.c:259  UCX  DEBUG   tcp_ep 0x60f000012100: created on iface 0x61c000007880, fd -1
[1733115448.644770] [10-16-43-32:1687395:1]       wireup_ep.c:489  UCX  DEBUG   ep 0x7fce52e7b0a0: wireup_ep 0x617000015080 created next_ep 0x60f000012100 to 10.16.43.32:8123 using tcp/lo
[1733115448.644787] [10-16-43-32:1687395:1]          wireup.c:1664 UCX  DEBUG ep 0x7fce52e7b0a0: send wireup request (flags=0x4a04091)
[1733115448.657102] [10-16-43-32:1687395:a]            sock.c:410  UCX  DEBUG [127.0.0.1:58765]<->[127.0.0.1:53838] is a connected pair
[1733115448.657148] [10-16-43-32:1687395:a]          tcp_ep.c:259  UCX  DEBUG tcp_ep 0x60f000017920: created on iface 0x61c000007880, fd 23
[1733115448.657164] [10-16-43-32:1687395:a]          tcp_cm.c:106  UCX  DEBUG tcp_ep 0x60f000017920: CLOSED -> RECV_MAGIC_NUMBER
[1733115448.657189] [10-16-43-32:1687395:a]          tcp_cm.c:841  UCX  DEBUG tcp_iface 0x61c000007880: accepted connection from 127.0.0.1:53838 on 127.0.0.1:58765 to tcp_ep 0x60f000017920 (fd 23)
[1733115448.657293] [10-16-43-32:1687395:1]          tcp_cm.c:106  UCX  DEBUG   tcp_ep 0x60f000012100: CLOSED -> ACCEPTING
[1733115448.657329] [10-16-43-32:1687395:1]          tcp_cm.c:106  UCX  DEBUG tcp_ep 0x60f000017920: RECV_MAGIC_NUMBER -> ACCEPTING
[1733115448.657353] [10-16-43-32:1687395:1]       wireup_ep.c:421  UCX  DEBUG ep 0x7fce52e7b0a0: destroy wireup ep 0x617000014280
[1733115448.657366] [10-16-43-32:1687395:1]       wireup_ep.c:421  UCX  DEBUG ep 0x7fce52e7b0a0: destroy wireup ep 0x617000014980
[1733115448.657378] [10-16-43-32:1687395:1]       wireup_ep.c:421  UCX  DEBUG ep 0x7fce52e7b0a0: destroy wireup ep 0x617000014d00
[1733115448.657384] [10-16-43-32:1687395:1]       wireup_ep.c:421  UCX  DEBUG ep 0x7fce52e7b0a0: destroy wireup ep 0x617000015080
[1733115448.657396] [10-16-43-32:1687395:1]       wireup_ep.c:421  UCX  DEBUG ep 0x7fce52e7b0a0: destroy wireup ep 0x617000014600
[1733115448.657436] [10-16-43-32:1687395:1]           mm_ep.c:69   UCX  DEBUG mm_ep 0x60e000060520: attached remote segment id 0xa18026 at 0x7fce2fa00000 cookie 0xbebebebebebebebe
[1733115448.657511] [10-16-43-32:1687395:1]          tcp_cm.c:96   UCX  DEBUG tcp_ep 0x60f000012100: ACCEPTING -> CONNECTED for the [127.0.0.1:58765]<->[127.0.0.1:57845]:5 connection [Tx:Rx]
[1733115448.657525] [10-16-43-32:1687395:1]          tcp_ep.c:358  UCX  DEBUG tcp_ep 0x60f000017920: purge outstanding operations with status Request canceled
[1733115448.657538] [10-16-43-32:1687395:1]          tcp_cm.c:106  UCX  DEBUG tcp_ep 0x60f000017920: ACCEPTING -> CLOSED
[1733115448.657549] [10-16-43-32:1687395:1]          tcp_ep.c:409  UCX  DEBUG tcp_ep 0x60f000017920: destroyed on iface 0x61c000007880
[2024-12-02 12:57:28.657] [info] [channel.cc:509] Ep flush ok
[2024-12-02 12:57:28.657] [info] [channel.cc:520] Worker flush ok

server:

[1733119302.442171] [10-16-43-32:1700050:0]          wireup.c:1214 UCX  DEBUG   ep 0x7f28c946c000: am_lane 1 wireup_msg_lane 4 cm_lane 0 keepalive_lane 1 reachable_mds 0xe
[1733119302.442180] [10-16-43-32:1700050:0]          wireup.c:1237 UCX  DEBUG   ep 0x7f28c946c000: lane[0]: cm rdmacm
[1733119302.442195] [10-16-43-32:1700050:0]          wireup.c:1237 UCX  DEBUG   ep 0x7f28c946c000: lane[1]:  4:sysv/memory.0 md[3]           -> addr[2].md[2]/sysv/sysdev[255] seg 4294967295 am am_bw#0 keepalive
[1733119302.442207] [10-16-43-32:1700050:0]          wireup.c:1237 UCX  DEBUG   ep 0x7f28c946c000: lane[2]:  5:posix/memory.0 md[4]          -> addr[3].md[3]/posix/sysdev[255] seg 4294967295
[1733119302.442220] [10-16-43-32:1700050:0]          wireup.c:1237 UCX  DEBUG   ep 0x7f28c946c000: lane[3]:  3:tcp/lo.0 md[2]                -> addr[1].md[1]/tcp/sysdev[255] seg 4294967295 rma_bw#0
[1733119302.442232] [10-16-43-32:1700050:0]          wireup.c:1237 UCX  DEBUG   ep 0x7f28c946c000: lane[4]:  2:tcp/ens4.0 md[2]              -> addr[0].md[1]/tcp/sysdev[255] seg 4294967295 rma_bw#1 wireup
[1733119302.442243] [10-16-43-32:1700050:0]          wireup.c:1240 UCX  DEBUG   ep 0x7f28c946c000: err mode 1, flags 0x2
[1733119302.442282] [10-16-43-32:1700050:0]           mm_ep.c:69   UCX  DEBUG   mm_ep 0x60e000001ee0: attached remote segment id 0xa28017 at 0x7f28c9403000 cookie 0xbebebebebebebebe
[1733119302.442335] [10-16-43-32:1700050:0]           mm_ep.c:203  UCX  DEBUG   created mm ep 0x60e000001ee0, connected to remote FIFO id 0xa28017
[1733119302.442356] [10-16-43-32:1700050:0]       wireup_ep.c:530  UCX  DEBUG   ep 0x7f28c946c000: wireup_ep 0x617000002000 set next_ep 0x60e000001ee0
[1733119302.442393] [10-16-43-32:1700050:0]           mm_ep.c:69   UCX  DEBUG   mm_ep 0x60e000001fc0: attached remote segment id 0xc00000044019ef4b at 0x7f28c9204000 cookie 0x80ff
[1733119302.442426] [10-16-43-32:1700050:0]           mm_ep.c:203  UCX  DEBUG   created mm ep 0x60e000001fc0, connected to remote FIFO id 0xc00000044019ef4b
[1733119302.442437] [10-16-43-32:1700050:0]       wireup_ep.c:530  UCX  DEBUG   ep 0x7f28c946c000: wireup_ep 0x617000002380 set next_ep 0x60e000001fc0
[1733119302.442453] [10-16-43-32:1700050:0]          tcp_ep.c:259  UCX  DEBUG   tcp_ep 0x60f0000042d0: created on iface 0x61c000006880, fd -1
[1733119302.442464] [10-16-43-32:1700050:0]       wireup_ep.c:489  UCX  DEBUG   ep 0x7f28c946c000: wireup_ep 0x617000002700 created next_ep 0x60f0000042d0 to <no debug data> using tcp/lo
[1733119302.442485] [10-16-43-32:1700050:0]          tcp_cm.c:106  UCX  DEBUG   tcp_ep 0x60f0000042d0: CLOSED -> ACCEPTING
[1733119302.442586] [10-16-43-32:1700050:0]           mm_ep.c:69   UCX  DEBUG mm_ep 0x60e000001ee0: attached remote segment id 0xa28018 at 0x7f28a6000000 cookie 0xbebebebebebebebe
[1733119302.442868] [10-16-43-32:1700050:a]            sock.c:410  UCX  DEBUG [127.0.0.1:57591]<->[127.0.0.1:40494] is a connected pair
[1733119302.442919] [10-16-43-32:1700050:a]          tcp_ep.c:259  UCX  DEBUG tcp_ep 0x60f000007840: created on iface 0x61c000006880, fd 19
[1733119302.442931] [10-16-43-32:1700050:a]          tcp_cm.c:106  UCX  DEBUG tcp_ep 0x60f000007840: CLOSED -> RECV_MAGIC_NUMBER
[1733119302.442950] [10-16-43-32:1700050:a]          tcp_cm.c:841  UCX  DEBUG tcp_iface 0x61c000006880: accepted connection from 127.0.0.1:40494 on 127.0.0.1:57591 to tcp_ep 0x60f000007840 (fd 19)
[1733119302.443108] [10-16-43-32:1700050:0]           mpool.c:281  UCX  DEBUG mpool uct_tcp_iface_rx_buf_mp: allocated chunk 0x7f28a68e5800 of 1049176 bytes with 8 elements
[1733119302.443147] [10-16-43-32:1700050:0]          tcp_cm.c:106  UCX  DEBUG tcp_ep 0x60f000007840: RECV_MAGIC_NUMBER -> ACCEPTING
[1733119302.443218] [10-16-43-32:1700050:0]          tcp_cm.c:96   UCX  DEBUG tcp_ep 0x60f0000042d0: ACCEPTING -> CONNECTED for the [127.0.0.1:57591]<->[127.0.0.1:39251]:3 connection [Tx:Rx]
[1733119302.443228] [10-16-43-32:1700050:0]          tcp_ep.c:358  UCX  DEBUG tcp_ep 0x60f000007840: purge outstanding operations with status Request canceled
[1733119302.443238] [10-16-43-32:1700050:0]          tcp_cm.c:106  UCX  DEBUG tcp_ep 0x60f000007840: ACCEPTING -> CLOSED
[1733119302.443245] [10-16-43-32:1700050:0]          tcp_ep.c:409  UCX  DEBUG tcp_ep 0x60f000007840: destroyed on iface 0x61c000006880
[1733119302.443258] [10-16-43-32:1700050:0]       wireup_ep.c:421  UCX  DEBUG ep 0x7f28c946c000: destroy wireup ep 0x617000001c80
[1733119302.443269] [10-16-43-32:1700050:0]       wireup_ep.c:421  UCX  DEBUG ep 0x7f28c946c000: destroy wireup ep 0x617000002000
[1733119302.443279] [10-16-43-32:1700050:0]       wireup_ep.c:421  UCX  DEBUG ep 0x7f28c946c000: destroy wireup ep 0x617000002380
[1733119302.443287] [10-16-43-32:1700050:0]       wireup_ep.c:421  UCX  DEBUG ep 0x7f28c946c000: destroy wireup ep 0x617000002700
[1733119302.443296] [10-16-43-32:1700050:0]       wireup_ep.c:421  UCX  DEBUG ep 0x7f28c946c000: destroy wireup ep 0x617000001900

[ivanallen]

If reconnect success.

client log:

[1733120664.107212] [10-16-43-32:1704567:1]      ucp_worker.c:1888 UCX  INFO    xrpc_channel intra-node cfg#3 tag(sysv/memory tcp/lo tcp/ens4)  rma(sysv/memory posix/memory)  am(sysv/memory tcp/lo tcp/ens4)  ka(sysv/memory)
[1733120664.107229] [10-16-43-32:1704567:1]          wireup.c:1214 UCX  DEBUG   ep 0x7f226221c000: am_lane 1 wireup_msg_lane 4 cm_lane 0 keepalive_lane 1 reachable_mds 0x1d
[1733120664.107238] [10-16-43-32:1704567:1]          wireup.c:1237 UCX  DEBUG   ep 0x7f226221c000: lane[0]: cm rdmacm
[1733120664.107253] [10-16-43-32:1704567:1]          wireup.c:1237 UCX  DEBUG   ep 0x7f226221c000: lane[1]:  3:sysv/memory.0 md[2]           -> addr[4].md[3]/sysv/sysdev[255] seg 4294967295 am am_bw#0 keepalive
[1733120664.107265] [10-16-43-32:1704567:1]          wireup.c:1237 UCX  DEBUG   ep 0x7f226221c000: lane[2]:  4:posix/memory.0 md[3]          -> addr[5].md[4]/posix/sysdev[255] seg 4294967295
[1733120664.107277] [10-16-43-32:1704567:1]          wireup.c:1237 UCX  DEBUG   ep 0x7f226221c000: lane[3]:  2:tcp/lo.0 md[1]                -> addr[3].md[2]/tcp/sysdev[255] seg 4294967295 rma_bw#0
[1733120664.107290] [10-16-43-32:1704567:1]          wireup.c:1237 UCX  DEBUG   ep 0x7f226221c000: lane[4]:  1:tcp/ens4.0 md[1]              -> addr[2].md[2]/tcp/sysdev[255] seg 4294967295 rma_bw#1 wireup
[1733120664.107297] [10-16-43-32:1704567:1]          wireup.c:1240 UCX  DEBUG   ep 0x7f226221c000: err mode 1, flags 0x2
[1733120664.107342] [10-16-43-32:1704567:1]           mm_ep.c:69   UCX  DEBUG   mm_ep 0x60e0000601a0: attached remote segment id 0xa38003 at 0x7f2241096000 cookie 0xbebebebebebebebe
[1733120664.107398] [10-16-43-32:1704567:1]           mm_ep.c:203  UCX  DEBUG   created mm ep 0x60e0000601a0, connected to remote FIFO id 0xa38003
[1733120664.107420] [10-16-43-32:1704567:1]       wireup_ep.c:530  UCX  DEBUG   ep 0x7f226221c000: wireup_ep 0x617000012d80 set next_ep 0x60e0000601a0
[1733120664.107447] [10-16-43-32:1704567:1]           mm_ep.c:69   UCX  DEBUG   mm_ep 0x60e000060280: attached remote segment id 0xc0000003401a026f at 0x7f224108d000 cookie 0x80ff
[1733120664.107477] [10-16-43-32:1704567:1]           mm_ep.c:203  UCX  DEBUG   created mm ep 0x60e000060280, connected to remote FIFO id 0xc0000003401a026f
[1733120664.107488] [10-16-43-32:1704567:1]       wireup_ep.c:530  UCX  DEBUG   ep 0x7f226221c000: wireup_ep 0x617000013100 set next_ep 0x60e000060280
[1733120664.107512] [10-16-43-32:1704567:1]          tcp_ep.c:259  UCX  DEBUG   tcp_ep 0x60f000011890: created on iface 0x61c000007880, fd -1
[1733120664.107524] [10-16-43-32:1704567:1]       wireup_ep.c:489  UCX  DEBUG   ep 0x7f226221c000: wireup_ep 0x617000013480 created next_ep 0x60f000011890 to 10.16.43.32:8123 using tcp/lo
[1733120664.107541] [10-16-43-32:1704567:1]          wireup.c:1664 UCX  DEBUG ep 0x7f226221c000: send wireup request (flags=0x4a04091)
[1733120664.107616] [10-16-43-32:1704567:1]           mpool.c:281  UCX  DEBUG mpool uct_tcp_iface_tx_buf_mp: allocated chunk 0x6310000a0800 of 66136 bytes with 8 elements
[1733120664.107734] [10-16-43-32:1704567:1]           mm_ep.c:69   UCX  DEBUG mm_ep 0x60e0000601a0: attached remote segment id 0xa38004 at 0x7f223ee00000 cookie 0xbebebebebebebebe
[1733120664.124955] [10-16-43-32:1704567:a]            sock.c:410  UCX  DEBUG [127.0.0.1:55481]<->[127.0.0.1:44522] is a connected pair
[1733120664.125035] [10-16-43-32:1704567:a]          tcp_ep.c:259  UCX  DEBUG tcp_ep 0x60f000017830: created on iface 0x61c000007880, fd 23
[1733120664.125055] [10-16-43-32:1704567:a]          tcp_cm.c:106  UCX  DEBUG tcp_ep 0x60f000017830: CLOSED -> RECV_MAGIC_NUMBER
[1733120664.125084] [10-16-43-32:1704567:a]          tcp_cm.c:841  UCX  DEBUG tcp_iface 0x61c000007880: accepted connection from 127.0.0.1:44522 on 127.0.0.1:55481 to tcp_ep 0x60f000017830 (fd 23)
[1733120664.125263] [10-16-43-32:1704567:1]          tcp_cm.c:106  UCX  DEBUG   tcp_ep 0x60f000011890: CLOSED -> ACCEPTING
[1733120664.125710] [10-16-43-32:1704567:1]           mpool.c:281  UCX  DEBUG mpool uct_tcp_iface_rx_buf_mp: allocated chunk 0x7f223ecfe800 of 1049176 bytes with 8 elements
[1733120664.125742] [10-16-43-32:1704567:1]          tcp_cm.c:106  UCX  DEBUG tcp_ep 0x60f000017830: RECV_MAGIC_NUMBER -> ACCEPTING
[1733120664.125763] [10-16-43-32:1704567:1]       wireup_ep.c:421  UCX  DEBUG ep 0x7f226221c000: destroy wireup ep 0x617000007b00
[1733120664.125776] [10-16-43-32:1704567:1]       wireup_ep.c:421  UCX  DEBUG ep 0x7f226221c000: destroy wireup ep 0x617000012d80
[1733120664.125785] [10-16-43-32:1704567:1]       wireup_ep.c:421  UCX  DEBUG ep 0x7f226221c000: destroy wireup ep 0x617000013100
[1733120664.125794] [10-16-43-32:1704567:1]       wireup_ep.c:421  UCX  DEBUG ep 0x7f226221c000: destroy wireup ep 0x617000013480
[1733120664.125804] [10-16-43-32:1704567:1]       wireup_ep.c:421  UCX  DEBUG ep 0x7f226221c000: destroy wireup ep 0x617000011500
[1733120664.125902] [10-16-43-32:1704567:1]          tcp_cm.c:96   UCX  DEBUG tcp_ep 0x60f000011890: ACCEPTING -> CONNECTED for the [127.0.0.1:55481]<->[127.0.0.1:47125]:3 connection [Tx:Rx]
[1733120664.125917] [10-16-43-32:1704567:1]          tcp_ep.c:358  UCX  DEBUG tcp_ep 0x60f000017830: purge outstanding operations with status Request canceled
[1733120664.125927] [10-16-43-32:1704567:1]          tcp_cm.c:106  UCX  DEBUG tcp_ep 0x60f000017830: ACCEPTING -> CLOSED
[1733120664.125933] [10-16-43-32:1704567:1]          tcp_ep.c:409  UCX  DEBUG tcp_ep 0x60f000017830: destroyed on iface 0x61c000007880
[2024-12-02 14:24:24.126] [info] [channel.cc:534] Received handshake message:worker_address {
  address: "0\325\333\374%\200\260=/\02310-16-43-32:1704559 \010>\275\014\335\005\244\'9G\213\2757\0066\000$.Pw\314\2533\000\222!\000\204o\002\032\000!\000cuw\314+2\000@\227P\000\000\000\000\000O\003\000\210\320]\000\277\000\234d\371\"\00
6\000\002\n\020+ \317\031\027\267Q8\314\0175K\327\34077\000\023#\000\202\245K\"\022\001\002>\275\014\335\005\244\'\271\230\000\000\360\000\000\000\000\317\031\027\267Q8S\236>K\327\34077\001\023#\000\202\270\025C\010>\275\014\335\005\244\'
9\215Sw\314+2\000\000pPw\314\2533\000O#\000\210\003\200\243\000\000\000\000\000D\010>\275\014\335\005\244\'9\247\323w\314+2\000\000pPw\314\2533\000O#\000\210o\002\032@\003\000\000\300\201\200"
}
 from:10.16.43.32:8123

server log:

[1733120664.124200] [10-16-43-32:1704559:0]      ucp_worker.c:1888 UCX  INFO    xrpc_server intra-node cfg#1 tag(sysv/memory tcp/lo tcp/ens4)  rma(sysv/memory posix/memory)  am(sysv/memory tcp/lo tcp/ens4)  ka(sysv/memory)
[1733120664.124219] [10-16-43-32:1704559:0]          wireup.c:1214 UCX  DEBUG   ep 0x7f8b31f89000: am_lane 1 wireup_msg_lane 4 cm_lane 0 keepalive_lane 1 reachable_mds 0xe
[1733120664.124231] [10-16-43-32:1704559:0]          wireup.c:1237 UCX  DEBUG   ep 0x7f8b31f89000: lane[0]: cm rdmacm
[1733120664.124246] [10-16-43-32:1704559:0]          wireup.c:1237 UCX  DEBUG   ep 0x7f8b31f89000: lane[1]:  4:sysv/memory.0 md[3]           -> addr[2].md[2]/sysv/sysdev[255] seg 4294967295 am am_bw#0 keepalive
[1733120664.124258] [10-16-43-32:1704559:0]          wireup.c:1237 UCX  DEBUG   ep 0x7f8b31f89000: lane[2]:  5:posix/memory.0 md[4]          -> addr[3].md[3]/posix/sysdev[255] seg 4294967295
[1733120664.124271] [10-16-43-32:1704559:0]          wireup.c:1237 UCX  DEBUG   ep 0x7f8b31f89000: lane[3]:  3:tcp/lo.0 md[2]                -> addr[1].md[1]/tcp/sysdev[255] seg 4294967295 rma_bw#0
[1733120664.124284] [10-16-43-32:1704559:0]          wireup.c:1237 UCX  DEBUG   ep 0x7f8b31f89000: lane[4]:  2:tcp/ens4.0 md[2]              -> addr[0].md[1]/tcp/sysdev[255] seg 4294967295 rma_bw#1 wireup
[1733120664.124293] [10-16-43-32:1704559:0]          wireup.c:1240 UCX  DEBUG   ep 0x7f8b31f89000: err mode 1, flags 0x2
[1733120664.124337] [10-16-43-32:1704559:0]           mm_ep.c:69   UCX  DEBUG   mm_ep 0x60e000001ee0: attached remote segment id 0xa38009 at 0x7f8b31f00000 cookie 0xbebebebebebebebe
[1733120664.124399] [10-16-43-32:1704559:0]           mm_ep.c:203  UCX  DEBUG   created mm ep 0x60e000001ee0, connected to remote FIFO id 0xa38009
[1733120664.124428] [10-16-43-32:1704559:0]       wireup_ep.c:530  UCX  DEBUG   ep 0x7f8b31f89000: wireup_ep 0x617000002000 set next_ep 0x60e000001ee0
[1733120664.124478] [10-16-43-32:1704559:0]           mm_ep.c:69   UCX  DEBUG   mm_ep 0x60e000001fc0: attached remote segment id 0xc0000004401a0277 at 0x7f8b31d04000 cookie 0x80ff
[1733120664.124518] [10-16-43-32:1704559:0]           mm_ep.c:203  UCX  DEBUG   created mm ep 0x60e000001fc0, connected to remote FIFO id 0xc0000004401a0277
[1733120664.124531] [10-16-43-32:1704559:0]       wireup_ep.c:530  UCX  DEBUG   ep 0x7f8b31f89000: wireup_ep 0x617000002380 set next_ep 0x60e000001fc0
[1733120664.124549] [10-16-43-32:1704559:0]          tcp_ep.c:259  UCX  DEBUG   tcp_ep 0x60f0000042d0: created on iface 0x61c000006880, fd -1
[1733120664.124560] [10-16-43-32:1704559:0]       wireup_ep.c:489  UCX  DEBUG   ep 0x7f8b31f89000: wireup_ep 0x617000002700 created next_ep 0x60f0000042d0 to <no debug data> using tcp/lo
[1733120664.124592] [10-16-43-32:1704559:0]          tcp_cm.c:96   UCX  DEBUG   tcp_ep 0x60f0000042d0: CLOSED -> CONNECTING for the [127.0.0.1:47125]<->[127.0.0.1:55481]:3 connection [-:Rx]
[1733120664.124623] [10-16-43-32:1704559:0]          tcp_cm.c:96   UCX  DEBUG   tcp_ep 0x60f0000042d0: CONNECTING -> CONNECTING for the [127.0.0.1:47125]<->[127.0.0.1:55481]:3 connection [-:Rx]
[1733120664.124869] [10-16-43-32:1704559:0]            sock.c:344  UCX  DEBUG   connect(fd=19, src_addr=127.0.0.1:44522 dest_addr=127.0.0.1:55481): Success
[1733120664.124919] [10-16-43-32:1704559:0]          tcp_cm.c:96   UCX  DEBUG   tcp_ep 0x60f0000042d0: CONNECTING -> CONNECTED for the [127.0.0.1:47125]<->[127.0.0.1:55481]:3 connection [-:Rx]
[1733120664.125072] [10-16-43-32:1704559:0]           mm_ep.c:69   UCX  DEBUG mm_ep 0x60e000001ee0: attached remote segment id 0xa3800a at 0x7f8b0ec00000 cookie 0xbebebebebebebebe
[1733120664.125838] [10-16-43-32:1704559:0]       wireup_ep.c:421  UCX  DEBUG ep 0x7f8b31f89000: destroy wireup ep 0x617000001c80
[1733120664.125855] [10-16-43-32:1704559:0]       wireup_ep.c:421  UCX  DEBUG ep 0x7f8b31f89000: destroy wireup ep 0x617000002000
[1733120664.125873] [10-16-43-32:1704559:0]       wireup_ep.c:421  UCX  DEBUG ep 0x7f8b31f89000: destroy wireup ep 0x617000002380
[1733120664.125883] [10-16-43-32:1704559:0]       wireup_ep.c:421  UCX  DEBUG ep 0x7f8b31f89000: destroy wireup ep 0x617000002700
[1733120664.125903] [10-16-43-32:1704559:0]       wireup_ep.c:421  UCX  DEBUG ep 0x7f8b31f89000: destroy wireup ep 0x617000001900
[1733120664.135675] [10-16-43-32:1704559:0]          ucp_ep.c:404  UCX  DEBUG created ep 0x7f8b31f890a0 to 10-16-43-32:1704567 remote-request
[1733120664.136814] [10-16-43-32:1704559:0]   +------------------------------+-------------------------------------------------------------+
[1733120664.136830] [10-16-43-32:1704559:0]   | xrpc_server intra-node cfg#2 | remote memory write by ucp_put* from host memory to host    |
[1733120664.136837] [10-16-43-32:1704559:0]   +------------------------------+-----------------------------------------------+-------------+
[1733120664.136844] [10-16-43-32:1704559:0]   |                       0..inf | software emulation                            | sysv/memory |
[1733120664.136850] [10-16-43-32:1704559:0]   +------------------------------+-----------------------------------------------+-------------+