Menu ▾ ▴

#270 UDP streams w/ >1 client IP crash without -B set

1.0
accepted
None
2023-09-15
2023-09-06
No

The issue occurs when the client has >1 ip address, either ipv6 or ipv4 of which both are reachable
Tested on both 2-1-4 and 2-1-9.

This was observed on both Linux and BSD.
Linux: Generates ~800 sockets and crashes
BSD: Fails on listener bind failed or connect UDP failed after attempting to bind() or connect() with EADDRINUSE

# iperf -us &
[1] 57139233
# ------------------------------------------------------------
Server listening on UDP port 5001
UDP buffer size: 41.1 KByte (default)
------------------------------------------------------------

# [  1] local 192.168.0.31 port 5001 connected with 192.168.0.2 port 45547
listener bind failed: Address already in use
[root@linux ~]$ iperf -uc 192.168.0.68 -P 3 -b 50M
[  2] local 192.168.0.2 port 51433 connected with 192.168.0.68 port 5001
------------------------------------------------------------
Client connecting to 192.168.0.68, UDP port 5001
Sending 1470 byte datagrams, IPG target: 224.30 us (kalman adjust)
UDP buffer size:  208 KByte (default)
------------------------------------------------------------
[  3] local 192.168.0.2 port 54779 connected with 192.168.0.68 port 5001
[  1] local 192.168.0.2 port 45547 connected with 192.168.0.68 port 5001
[ ID] Interval       Transfer     Bandwidth
[  1] 0.0000-10.0004 sec  62.5 MBytes  52.4 Mbits/sec
[  1] Sent 44587 datagrams
[  2] 0.0000-10.0004 sec  62.5 MBytes  52.4 Mbits/sec
[  2] Sent 44587 datagrams
[  3] 0.0000-10.0004 sec  62.5 MBytes  52.4 Mbits/sec
[  3] Sent 44587 datagrams
[SUM] 0.0000-10.0004 sec   188 MBytes   157 Mbits/sec
[SUM-3] Sent 133761 datagrams
[  4] WARNING: did not receive ack of last datagram after 10 tries.
[  3] WARNING: did not receive ack of last datagram after 10 tries.
[  5] WARNING: did not receive ack of last datagram after 10 tries.

Seen above the server accepts the connection on .31 though the client assumes it connected on .68.

From what I've looked at the connect() call in udp_accept() looks like the cause, as it chooses the best routable ip, which may not be the one the client is addressing, so all further messages end up at the listening socket rather than the 'connected' UDP socket. Attempted to remedy this by creating a new socket on receipt to the listening socket but further messages just went to the listening socket.

This can be worked around by specifying -B on the server side.

Discussion

1 2 > >> (Page 1 of 2)
  • Robert McMahon

    Robert McMahon - 2023-09-06
    • status: open --> accepted
     
  • Robert McMahon

    Robert McMahon - 2023-09-06

    Can you compile from master? I did some fixes around UDP accept after 2.1.9. There were regressions introduced and fixed after 2.1.9

     
    • Ryan Campbell

      Ryan Campbell - 2023-09-06

      Compiled from master (both client and server), had the same output on Linux except now it segfaults when the client uses the same address that the server's connect() binds

      192.168.0.2 and 192.168.0.102 are on the server

      -c -s version result
      192.168.0.2 master segfault?
      192.168.0.2 2.1.9 expected
      192.168.0.102 master crash
      192.168.0.102 2.1.9 crash

      Client

      $ ./iperf -v
      iperf version 2.1.n (3 September 2023) pthreads
      $ ./iperf -uc 192.168.0.2 -P 3 -b 50M
      $ ./iperf -uc 192.168.0.102 -P 3 -b 50M
      

      master server w/ client using 192.168.0.2

      [root@linux src]$ ./iperf -us &
      [1] 12616
      [root@linux src]$ ------------------------------------------------------------
      Server listening on UDP port 5001
      UDP buffer size:  208 KByte (default)
      ------------------------------------------------------------
      [  1] local 192.168.0.2 port 5001 connected with 192.168.0.20 port 44084
      [  2] local 192.168.0.2 port 5001 connected with 192.168.0.20 port 38469
      [  3] local 192.168.0.2 port 5001 connected with 192.168.0.20 port 39523
      [ ID] Interval       Transfer     Bandwidth        Jitter   Lost/Total Datagrams
      [  3] 0.00-10.00 sec  62.5 MBytes  52.4 Mbits/sec   0.002 ms 14/44586 (0.031%)
      [  2] 0.00-10.00 sec  62.5 MBytes  52.4 Mbits/sec   0.003 ms 6/44586 (0.013%)
      [  2] 0.00-10.00 sec  1 datagrams received out-of-order
      [  1] 0.00-10.00 sec  62.5 MBytes  52.4 Mbits/sec   0.001 ms 0/44586 (0%)
      [  1] 0.00-10.00 sec  8 datagrams received out-of-order
      [ ID] Interval       Transfer     Bandwidth
      
      [1]+  Segmentation fault      (core dumped) ./iperf -us
      

      2.1.9 server w/ client using 192.168.0.2

      [root@linux src]$ iperf -us &
      [1] 12633
      [root@linux src]$ ------------------------------------------------------------
      Server listening on UDP port 5001
      UDP buffer size:  208 KByte (default)
      ------------------------------------------------------------
      [  1] local 192.168.0.2 port 5001 connected with 192.168.0.20 port 39070
      [  2] local 192.168.0.2 port 5001 connected with 192.168.0.20 port 33730
      [  3] local 192.168.0.2 port 5001 connected with 192.168.0.20 port 57340
      [ ID] Interval       Transfer     Bandwidth        Jitter   Lost/Total Datagrams
      [  3] 0.0000-9.9973 sec  62.5 MBytes  52.4 Mbits/sec   0.002 ms 14/44586 (0.031%)
      [  2] 0.0000-9.9989 sec  62.5 MBytes  52.4 Mbits/sec   0.001 ms 6/44586 (0.013%)
      [  2] 0.0000-9.9989 sec  1 datagrams received out-of-order
      [  1] 0.0000-10.0001 sec  62.5 MBytes  52.4 Mbits/sec   0.002 ms 0/44586 (0%)
      [  1] 0.0000-10.0001 sec  4 datagrams received out-of-order
      [ ID] Interval       Transfer     Bandwidth
      [SUM] 0.0000-10.0001 sec   187 MBytes   157 Mbits/sec   16/133758 (0.012%)
      [SUM] 0.0000-10.0001 sec  5 datagrams received out-of-order
      [root@linux src]$ iperf -v
      iperf version 2.1.9 (14 March 2023) pthreads
      

      master server w/ client using 192.168.0.102

      iperf version 2.1.n (3 September 2023) pthreads
      [root@linux src]$ ./iperf -us
      ------------------------------------------------------------
      Server listening on UDP port 5001
      UDP buffer size:  208 KByte (default)
      ------------------------------------------------------------
      [  1] local 192.168.0.2 port 5001 connected with 192.168.0.20 port 45411
      [  2] local 192.168.0.2 port 5001 connected with 192.168.0.20 port 51802
      ...........................
      [956] local 192.168.0.2 port 5001 connected with 192.168.0.20 port 33642
      [957] local 192.168.0.2 port 5001 connected with 192.168.0.20 port 33642
      socket failed: Too many open files
      SO_REUSEADDR failed: Bad file descriptor
      listener bind failed: Bad file descriptor
      [958] local 192.168.0.2 port 5001 connected with 192.168.0.20 port 33642
      ......................
      [977] local 192.168.0.2 port 5001 connected with 192.168.0.20 port 33642
      [978] local 192.168.0.2 port 5001 connected with 192.168.0.20 port 33642
      
       

      Last edit: Ryan Campbell 2023-09-06
      • Robert McMahon

        Robert McMahon - 2023-09-06

        I introduced a regression in UDP recently too. Need the latest per this commit. You'll need to git pull to get it.

        root@raspberrypi:/usr/local/src/iperf2-code# src/iperf -s -u
        ------------------------------------------------------------
        Server listening on UDP port 5001
        UDP buffer size:  208 KByte (default)
        ------------------------------------------------------------
        [  1] local 192.168.1.33 port 5001 connected with 192.168.1.32 port 39170
        [  2] local 192.168.1.33 port 5001 connected with 192.168.1.32 port 60319
        [  3] local 192.168.1.33 port 5001 connected with 192.168.1.32 port 53184
        [ ID] Interval       Transfer     Bandwidth        Jitter   Lost/Total Datagrams
        [  3] 0.00-10.00 sec  62.5 MBytes  52.4 Mbits/sec   0.205 ms 14/44585 (0.031%)
        [  2] 0.00-10.00 sec  62.5 MBytes  52.4 Mbits/sec   0.209 ms 6/44585 (0.013%)
        [  1] 0.00-10.00 sec  62.5 MBytes  52.4 Mbits/sec   0.211 ms 0/44586 (0%)
        [  1] 0.00-10.00 sec  5 datagrams received out-of-order
        [ ID] Interval       Transfer     Bandwidth
        [SUM] 0.00-10.00 sec   187 MBytes   157 Mbits/sec   15/133756 (0.011%)
        [SUM] 0.00-10.00 sec  5 datagrams received out-of-order
        
         
        • Robert McMahon

          Robert McMahon - 2023-09-06
          root@raspberrypi:/usr/local/src/iperf2-code# iperf -v
          iperf version 2.1.n (6 September 2023) pthreads
          root@raspberrypi:/usr/local/src/iperf2-code# src/iperf -s -u
          ------------------------------------------------------------
          Server listening on UDP port 5001
          UDP buffer size:  208 KByte (default)
          ------------------------------------------------------------
          [  1] local 192.168.1.33 port 5001 connected with 192.168.1.32 port 55458
          [  2] local 192.168.1.33 port 5001 connected with 192.168.1.32 port 45291
          [  3] local 192.168.1.33 port 5001 connected with 192.168.1.32 port 35163
          [ ID] Interval       Transfer     Bandwidth        Jitter   Lost/Total Datagrams
          [  3] 0.00-10.00 sec  62.5 MBytes  52.4 Mbits/sec   0.212 ms 8/44585 (0.018%)
          [  2] 0.00-10.00 sec  62.5 MBytes  52.4 Mbits/sec   0.213 ms 7/44586 (0.016%)
          [  2] 0.00-10.00 sec  1 datagrams received out-of-order
          [  1] 0.00-10.00 sec  62.5 MBytes  52.4 Mbits/sec   0.219 ms 0/44586 (0%)
          [  1] 0.00-10.00 sec  4 datagrams received out-of-order
          [ ID] Interval       Transfer     Bandwidth
          [SUM] 0.00-10.00 sec   187 MBytes   157 Mbits/sec   11/133757 (0.0082%)
          [SUM] 0.00-10.00 sec  5 datagrams received out-of-order
          
          root@raspberrypi:/usr/local/src/iperf2-code# src/iperf -v
          iperf version 2.1.9 (14 March 2023) pthreads
          root@raspberrypi:/usr/local/src/iperf2-code# src/iperf -uc 192.168.1.33 -P 3 -b 50M
          ------------------------------------------------------------
          Client connecting to 192.168.1.33, UDP port 5001
          Sending 1470 byte datagrams, IPG target: 224.30 us (kalman adjust)
          UDP buffer size:  208 KByte (default)
          ------------------------------------------------------------
          [  1] local 192.168.1.32 port 35163 connected with 192.168.1.33 port 5001
          [  3] local 192.168.1.32 port 55458 connected with 192.168.1.33 port 5001
          [  2] local 192.168.1.32 port 45291 connected with 192.168.1.33 port 5001
          [ ID] Interval       Transfer     Bandwidth
          [  3] 0.00-10.00 sec  62.5 MBytes  52.4 Mbits/sec
          [  3] Sent 44587 datagrams
          [  1] 0.00-10.00 sec  62.5 MBytes  52.4 Mbits/sec
          [  1] Sent 44586 datagrams
          [  2] 0.00-10.00 sec  62.5 MBytes  52.4 Mbits/sec
          [  2] Sent 44587 datagrams
          [SUM] 0.00-10.00 sec   188 MBytes   157 Mbits/sec
          [SUM-3] Sent 133760 datagrams
          [  2] Server Report:
          [ ID] Interval       Transfer     Bandwidth        Jitter   Lost/Total Datagrams
          [  2] 0.00-10.00 sec  62.5 MBytes  52.4 Mbits/sec   0.213 ms 7/44586 (0.016%)
          [  2] 0.00-10.00 sec  1 datagrams received out-of-order
          [  3] Server Report:
          [ ID] Interval       Transfer     Bandwidth        Jitter   Lost/Total Datagrams
          [  3] 0.00-10.00 sec  62.5 MBytes  52.4 Mbits/sec   0.219 ms 0/44586 (0%)
          [  3] 0.00-10.00 sec  4 datagrams received out-of-order
          [  1] Server Report:
          [ ID] Interval       Transfer     Bandwidth        Jitter   Lost/Total Datagrams
          [  1] 0.00-10.00 sec  62.5 MBytes  52.4 Mbits/sec   0.211 ms 8/44585 (0.018%)
          
           
        • Ryan Campbell

          Ryan Campbell - 2023-09-06

          No longer segfaulting on master w/ 192.168.0.2, but still seeing the same behaviour w/ 192.168.0.102

          $ ./iperf -v
          iperf version 2.1.n (6 September 2023) pthreads
          $ ./iperf -uc 192.168.0.102 -P 3 -b 50M
          
          [root@linux src]$ ./iperf -v
          iperf version 2.1.n (6 September 2023) pthreads
          [root@linux src]$ ./iperf -us
          ------------------------------------------------------------
          Server listening on UDP port 5001
          UDP buffer size:  208 KByte (default)
          ------------------------------------------------------------
          [  1] local 192.168.0.2 port 5001 connected with 192.168.0.20 port 46390
          [  2] local 192.168.0.2 port 5001 connected with 192.168.0.20 port 55538
          [  3] local 192.168.0.2 port 5001 connected with 192.168.0.20 port 55538
          [  4] local 192.168.0.2 port 5001 connected with 192.168.0.20 port 55538
          [  5] local 192.168.0.2 port 5001 connected with 192.168.0.20 port 55538
          [  6] local 192.168.0.2 port 5001 connected with 192.168.0.20 port 55538
          ............................
          [435] local 192.168.0.2 port 5001 connected with 192.168.0.20 port 55538
          [436] local 192.168.0.2 port 5001 connected with 192.168.0.20 port 55538
          socket failed: Too many open files
          SO_REUSEADDR failed: Bad file descriptor
          listener bind failed: Bad file descriptor
          [437] local 192.168.0.2 port 5001 connected with 192.168.0.20 port 43854
          [438] local 192.168.0.2 port 5001 connected with 192.168.0.20 port 55538
          ............................
          [448] local 192.168.0.2 port 5001 connected with 192.168.0.20 port 55538
          [449] local 192.168.0.2 port 5001 connected with 192.168.0.20 port 55538
          
           
          • Robert McMahon

            Robert McMahon - 2023-09-06

            Too many open files seems like an os thing vs an iperf thing (though iperf may have stale open files - hopefully not.) I'm not great a debug here but the output of lsof might help.

             
            • Robert McMahon

              Robert McMahon - 2023-09-06

              hmm, looking closer, the multiple opens to port 55538 are a problem. Not sure why that's happening.

              Can you run the server after compiling with debug?

              • ./configure --enable-thread-debug
              • make clean; make -j

              Thanks
              Bob

              Output is very chatty

              root@raspberrypi:/usr/local/src/iperf2-code# src/iperf -s -u
              THREAD(10645):[12:14:43.221909] Copy thread settings (malloc) from/to=0x559a7aceb0/0x559a7adbd0 report/sum/fullduplex (nil)/(nil)/(nil)
              THREAD(10645):[12:14:43.222545] Copy Settings: MBUF malloc 1982 bytes (0x559a7ae850)
              THREAD(10645):[12:14:43.222939] Thread_run_wrapper(0x559a7adbd0 mode=3) thread counts tot/trfc=1/0 (id=-1889140288)
              THREAD(10646):[12:14:43.223148] Reporter thread started
              THREAD(10645):[12:14:43.223692] Thread_run_wrapper(0x559a7aceb0 mode=7) thread counts tot/trfc=2/0 (id=-1897532992)
              THREAD(10646):[12:14:43.223915] Reporter await done
              THREAD(10647):[12:14:43.224314] Listener main loop port 5001 
              THREAD(10647):[12:14:43.224489] Set socket IP_TOS to 0x0
              THREAD(10647):[12:14:43.224641] Alloc common rpt/com/size 0x7f80000c20/0x7f80000e60/680
              THREAD(10647):[12:14:43.224722] Init settings report hdr/rpt/com 0x7f80000c00/0x7f80000c20/0x7f80000e60
              THREAD(10647):[12:14:43.224846] Jobq *POST* report 0x7f80000c00 (settings)
              THREAD(10647):[12:14:43.225008] Copy thread settings (malloc) from/to=0x559a7aceb0/0x7f80001130 report/sum/fullduplex (nil)/(nil)/(nil)
              THREAD(10647):[12:14:43.225154] Copy Settings: MBUF malloc 1982 bytes (0x7f80001700)
              THREAD(10647):[12:14:43.225288] Listener thread listening for UDP (sock=3)
              THREAD(10646):[12:14:43.225429] Jobq *WAIT* exit  (nil)/0x7f80000c00 cond=0x5572491b50 threads u/t=2/0
              THREAD(10646):[12:14:43.225539] Jobq *ROOT* 0x7f80000c00 (last=(nil))
              ------------------------------------------------------------
              Server listening on UDP port 5001
              UDP buffer size:  208 KByte (default)
              ------------------------------------------------------------
              THREAD(10646):[12:14:43.225869] Jobq *FREE* report hdr/rpt 0x7f80000c00/0x7f80000c20 (settings)
              THREAD(10646):[12:14:43.225942] Free common=0x7f80000e60
              THREAD(10646):[12:14:43.226025] Jobq *REMOVE* 0x7f80000c00
              THREAD(10646):[12:14:44.226214] Jobq *WAIT* exit  (nil)/(nil) cond=0x5572491b50 threads u/t=2/0
              THREAD(10646):[12:14:45.226454] Jobq *WAIT* exit  (nil)/(nil) cond=0x5572491b50 threads u/t=2/0
              THREAD(10647):[12:14:45.897183] rcvfrom peer: 192.168.1.32 port 52196 len=1470
              THREAD(10647):[12:14:45.897378] Alloc common rpt/com/size 0x7f80002090/0x7f80002a30/680
              THREAD(10647):[12:14:45.897456] Init sum report 0x7f80002050 id=1
              THREAD(10647):[12:14:45.897520] Sum multiheader 0x7f80002050 ref=0->1
              THREAD(10647):[12:14:45.897590] active table: new entry 192.168.1.32 port 52196 (flag=1) rootp=0x7f80001f30 entryp=0x7f80001f30 totcnt/activecnt/hostcnt = 1/1/1
              THREAD(10647):[12:14:45.898345] Listener thread accepted server sock=3 transferID
              THREAD(10647):[12:14:45.898461] UDP test flags = 48010098
              THREAD(10647):[12:14:45.898549] Alloc common rpt/com/size 0x7f80002df0/0x7f80002fe0/680
              THREAD(10647):[12:14:45.898637] Init connection report hdr/rpt/com 0x7f80002dd0/0x7f80002df0/0x7f80002fe0
              THREAD(10647):[12:14:45.898701] Jobq *POST* report 0x7f80002dd0 (connection)
              THREAD(10646):[12:14:45.898952] Jobq *WAIT* exit  (nil)/0x7f80002dd0 cond=0x5572491b50 threads u/t=3/1
              THREAD(10646):[12:14:45.899178] Jobq *ROOT* 0x7f80002dd0 (last=(nil))
              [  1] local 192.168.1.33 port 5001 connected with 192.168.1.32 port 52196
              THREAD(10648):[12:14:45.899280] spawn server settings=0x7f80001130 GroupSumReport=0x7f80002050 sock=3
              THREAD(10648):[12:14:45.899593] Server constructor with thread=0x7f80001130 sum=0x7f80002050 (sock=3)
              THREAD(10646):[12:14:45.899702] Jobq *FREE* report hdr/rpt 0x7f80002dd0/0x7f80002df0 (connection)
              THREAD(10648):[12:14:45.899791] Alloc common rpt/com/size 0x7f84000eb0/0x7f840017d0/680
              THREAD(10648):[12:14:45.899936] Init 10000 element packet ring=0x7f84001b30 consumer=0x5572491b50 producer=0x7f800014c0 total rings=1 enable=1
              THREAD(10648):[12:14:45.900017] Init data report hdr/rpt/com=0x7f84000e50/0x7f84000e70/0x7f840017d0 multireport/fullduplex=0x7f80002050/(nil) pring(bytes)/cond=0x7f84001b30(2720056)/0x7f800014c0 (socket=3)
              THREAD(10648):[12:14:45.900099] Server(3) report start=1694027685.897120 next=0.0
              THREAD(10648):[12:14:45.900177] Jobq *POST* report 0x7f84000e50 (data)
              THREAD(10646):[12:14:45.900278] Free common=0x7f80002fe0
              THREAD(10647):[12:14:45.900622] Thread_run_wrapper(0x7f80001130 mode=1) thread counts tot/trfc=3/1 (id=-1905925696)
              THREAD(10647):[12:14:45.900724] Listener main loop port 5001 
              THREAD(10646):[12:14:45.900818] Jobq *REMOVE* 0x7f80002dd0
              THREAD(10646):[12:14:45.900908] Jobq *ROOT* 0x7f84000e50 (last=(nil))
              THREAD(10647):[12:14:45.901239] Set socket IP_TOS to 0x0
              THREAD(10647):[12:14:45.901375] Copy thread settings (malloc) from/to=0x559a7aceb0/0x7f80003a70 report/sum/fullduplex (nil)/(nil)/(nil)
              THREAD(10647):[12:14:45.901479] Copy Settings: MBUF malloc 1982 bytes (0x7f80003fc0)
              THREAD(10647):[12:14:45.901549] Listener thread listening for UDP (sock=4)
              THREAD(10647):[12:14:45.901636] rcvfrom peer: 192.168.1.32 port 37094 len=1470
              THREAD(10647):[12:14:45.901704] active table: compare table entry client ip/port 192.168.1.32/52196 against host 192.168.1.32/37094 (miss)
              THREAD(10647):[12:14:45.901778] active table: compare table entry client ip 192.168.1.32/52196 against host 192.168.1.32/37094 (match)
              THREAD(10647):[12:14:45.901841] Sum multiheader 0x7f80002050 ref=1->2
              THREAD(10647):[12:14:45.901902] active table: incr entry 192.168.1.32 port 52196 (flag=1) rootp=0x7f80001f30 entryp=0x7f80001f30 totcnt/activecnt/hostcnt = 2/1/2
              THREAD(10647):[12:14:45.902502] Listener thread accepted server sock=4 transferID
              THREAD(10647):[12:14:45.902608] UDP test flags = 48010098
              THREAD(10647):[12:14:45.902689] Alloc common rpt/com/size 0x7f800034f0/0x7f80004790/680
              THREAD(10647):[12:14:45.902770] Init connection report hdr/rpt/com 0x7f800034d0/0x7f800034f0/0x7f80004790
              THREAD(10647):[12:14:45.902838] Jobq *POST* report 0x7f800034d0 (connection)
              THREAD(10647):[12:14:45.903186] Thread_run_wrapper(0x7f80003a70 mode=1) thread counts tot/trfc=4/2 (id=-1917042240)
              THREAD(10647):[12:14:45.903274] Listener main loop port 5001 
              THREAD(10649):[12:14:45.903369] spawn server settings=0x7f80003a70 GroupSumReport=0x7f80002050 sock=4
              THREAD(10649):[12:14:45.903827] Server constructor with thread=0x7f80003a70 sum=0x7f80002050 (sock=4)
              THREAD(10647):[12:14:45.903922] Set socket IP_TOS to 0x0
              THREAD(10649):[12:14:45.904027] Alloc common rpt/com/size 0x7f78000eb0/0x7f780017d0/680
              THREAD(10647):[12:14:45.904155] Copy thread settings (malloc) from/to=0x559a7aceb0/0x7f80004b70 report/sum/fullduplex (nil)/(nil)/(nil)
              THREAD(10647):[12:14:45.904243] Copy Settings: MBUF malloc 1982 bytes (0x7f800050c0)
              THREAD(10647):[12:14:45.904313] Listener thread listening for UDP (sock=5)
              THREAD(10647):[12:14:45.904403] rcvfrom peer: 192.168.1.32 port 36968 len=1470
              THREAD(10647):[12:14:45.904485] active table: compare table entry client ip/port 192.168.1.32/52196 against host 192.168.1.32/36968 (miss)
              THREAD(10647):[12:14:45.904568] active table: compare table entry client ip 192.168.1.32/52196 against host 192.168.1.32/36968 (match)
              THREAD(10647):[12:14:45.904646] Sum multiheader 0x7f80002050 ref=2->3
              THREAD(10647):[12:14:45.904715] active table: incr entry 192.168.1.32 port 52196 (flag=1) rootp=0x7f80001f30 entryp=0x7f80001f30 totcnt/activecnt/hostcnt = 3/1/3
              THREAD(10649):[12:14:45.904835] Init 10000 element packet ring=0x7f78001b30 consumer=0x5572491b50 producer=0x7f80003e00 total rings=2 enable=1
              THREAD(10649):[12:14:45.904990] Init data report hdr/rpt/com=0x7f78000e50/0x7f78000e70/0x7f780017d0 multireport/fullduplex=0x7f80002050/(nil) pring(bytes)/cond=0x7f78001b30(2720056)/0x7f80003e00 (socket=4)
              THREAD(10649):[12:14:45.905137] Server(4) report start=1694027685.901630 next=0.0
              THREAD(10649):[12:14:45.905481] Jobq *POST* report 0x7f78000e50 (data)
              THREAD(10647):[12:14:45.905578] Listener thread accepted server sock=5 transferID
              THREAD(10647):[12:14:45.905678] UDP test flags = 48010098
              THREAD(10647):[12:14:45.905760] Alloc common rpt/com/size 0x7f80005890/0x7f80005a80/680
              THREAD(10647):[12:14:45.905841] Init connection report hdr/rpt/com 0x7f80003780/0x7f80005890/0x7f80005a80
              THREAD(10647):[12:14:45.905909] Jobq *POST* report 0x7f80003780 (connection)
              THREAD(10647):[12:14:45.906331] Thread_run_wrapper(0x7f80004b70 mode=1) thread counts tot/trfc=5/3 (id=-1928158784)
              THREAD(10647):[12:14:45.906432] Listener main loop port 5001 
              THREAD(10647):[12:14:45.906540] Set socket IP_TOS to 0x0
              THREAD(10647):[12:14:45.906661] Copy thread settings (malloc) from/to=0x559a7aceb0/0x7f80005e60 report/sum/fullduplex (nil)/(nil)/(nil)
              THREAD(10647):[12:14:45.906738] Copy Settings: MBUF malloc 1982 bytes (0x7f800063b0)
              THREAD(10647):[12:14:45.906808] Listener thread listening for UDP (sock=6)
              THREAD(10650):[12:14:45.906940] spawn server settings=0x7f80004b70 GroupSumReport=0x7f80002050 sock=5
              THREAD(10650):[12:14:45.907126] Server constructor with thread=0x7f80004b70 sum=0x7f80002050 (sock=5)
              THREAD(10650):[12:14:45.907258] Alloc common rpt/com/size 0x7f7c000eb0/0x7f7c0017d0/680
              THREAD(10650):[12:14:45.907382] Init 10000 element packet ring=0x7f7c001b30 consumer=0x5572491b50 producer=0x7f80004f00 total rings=3 enable=1
              THREAD(10650):[12:14:45.907460] Init data report hdr/rpt/com=0x7f7c000e50/0x7f7c000e70/0x7f7c0017d0 multireport/fullduplex=0x7f80002050/(nil) pring(bytes)/cond=0x7f7c001b30(2720056)/0x7f80004f00 (socket=5)
              THREAD(10650):[12:14:45.907539] Server(5) report start=1694027685.904398 next=0.0
              THREAD(10650):[12:14:45.907609] Jobq *POST* report 0x7f7c000e50 (data)
              THREAD(10646):[12:14:45.917460] Jobq *ROOT* 0x7f800034d0 (last=0x7f84000e50)
              [  2] local 192.168.1.33 port 5001 connected with 192.168.1.32 port 37094
              THREAD(10646):[12:14:45.917622] Jobq *FREE* report hdr/rpt 0x7f800034d0/0x7f800034f0 (connection)
              THREAD(10646):[12:14:45.917791] Free common=0x7f80004790
              THREAD(10646):[12:14:45.917854] Jobq *REMOVE* 0x7f800034d0
              [  3] local 192.168.1.33 port 5001 connected with 192.168.1.32 port 36968
              THREAD(10646):[12:14:45.918020] Jobq *FREE* report hdr/rpt 0x7f80003780/0x7f80005890 (connection)
              THREAD(10646):[12:14:45.918082] Free common=0x7f80005a80
              THREAD(10646):[12:14:45.918189] Jobq *REMOVE* 0x7f80003780
              THREAD(10649):[12:14:55.897122] Reporting last packet for 0x7f78000e70  qdepth=49 sock=4
              THREAD(10649):[12:14:55.897281] Traffic thread awaiting reporter to be done with 0x7f78000e70 and cond 0x7f80003e00
              THREAD(10648):[12:14:55.897711] Reporting last packet for 0x7f84000e70  qdepth=50 sock=3
              THREAD(10648):[12:14:55.897792] Traffic thread awaiting reporter to be done with 0x7f84000e70 and cond 0x7f800014c0
              THREAD(10650):[12:14:55.897869] Reporting last packet for 0x7f7c000e70  qdepth=51 sock=5
              THREAD(10650):[12:14:55.897947] Traffic thread awaiting reporter to be done with 0x7f7c000e70 and cond 0x7f80004f00
              [ ID] Interval       Transfer     Bandwidth        Jitter   Lost/Total Datagrams
              [  3] 0.00-9.99 sec  62.5 MBytes  52.4 Mbits/sec   0.209 ms 33/44586 (0.074%)
              THREAD(10646):[12:14:55.902269] Jobq *REMOVE* 0x7f7c000e50
              [  2] 0.00-10.00 sec  62.5 MBytes  52.4 Mbits/sec   0.208 ms 18/44585 (0.04%)
              [  2] 0.00-10.00 sec  3 datagrams received out-of-order
              THREAD(10650):[12:14:55.902341] UDP server send done-ack w/server-stats to client (sock=5)
              THREAD(10646):[12:14:55.902501] Jobq *REMOVE* 0x7f78000e50
              [  1] 0.00-10.00 sec  62.5 MBytes  52.4 Mbits/sec   0.208 ms 0/44586 (0%)
              [  1] 0.00-10.00 sec  13 datagrams received out-of-order
              [ ID] Interval       Transfer     Bandwidth
              [SUM] 0.00-10.00 sec   187 MBytes   157 Mbits/sec   38/133757 (0.028%)
              [SUM] 0.00-10.00 sec  16 datagrams received out-of-order
              THREAD(10646):[12:14:55.902743] Jobq *REMOVE* 0x7f84000e50
              THREAD(10648):[12:14:55.902867] UDP server send done-ack w/server-stats to client (sock=3)
              THREAD(10649):[12:14:55.903008] UDP server send done-ack w/server-stats to client (sock=4)
              THREAD(10650):[12:14:56.152851] UDP server detected silence - server stats assumed received by client
              THREAD(10650):[12:14:56.152974] udp close sock=5
              THREAD(10650):[12:14:56.153135] Sum multiheader 0x7f80002050 ref=3->2
              THREAD(10650):[12:14:56.153218] active table: decr 192.168.1.32 port 52196 (flag=1) rootp=0x7f80001f30 entryp=0x7f80001f30 totcnt/activecnt/hostcnt = 3/1/2
              THREAD(10650):[12:14:56.153308] Jobq *FREE* report hdr/rpt 0x7f7c000e50/0x7f7c000e70 (data)
              THREAD(10650):[12:14:56.153383] Free report hdr=0x7f7c000e70 reporter thread suspend count=618 packetring=0x7f7c001b30 histo=(nil) frame histo=(nil)
              THREAD(10650):[12:14:56.153464] Free packet ring=0x7f7c001b30 producer=0x7f80004f00 (consumer=0x5572491b50) awaits = 0 total rings = 2
              THREAD(10648):[12:14:56.153561] UDP server detected silence - server stats assumed received by client
              THREAD(10648):[12:14:56.153650] udp close sock=3
              THREAD(10648):[12:14:56.153772] Sum multiheader 0x7f80002050 ref=2->1
              THREAD(10648):[12:14:56.153861] active table: decr 192.168.1.32 port 52196 (flag=1) rootp=0x7f80001f30 entryp=0x7f80001f30 totcnt/activecnt/hostcnt = 3/1/1
              THREAD(10648):[12:14:56.153935] Jobq *FREE* report hdr/rpt 0x7f84000e50/0x7f84000e70 (data)
              THREAD(10648):[12:14:56.154012] Free report hdr=0x7f84000e70 reporter thread suspend count=618 packetring=0x7f84001b30 histo=(nil) frame histo=(nil)
              THREAD(10648):[12:14:56.154090] Free packet ring=0x7f84001b30 producer=0x7f800014c0 (consumer=0x5572491b50) awaits = 0 total rings = 1
              THREAD(10649):[12:14:56.154511] UDP server detected silence - server stats assumed received by client
              THREAD(10649):[12:14:56.154785] udp close sock=4
              THREAD(10650):[12:14:56.155080] Free common=0x7f7c0017d0
              THREAD(10650):[12:14:56.155184] Server destructor sock=5 fullduplex=false
              THREAD(10649):[12:14:56.155276] active table: delete 192.168.1.32 port 52196 (flag=1) rootp=0x7f80001f30 entryp=0x7f80001f30 totcnt/activecnt/hostcnt = 3/0/0
              THREAD(10649):[12:14:56.155553] Free sum report hdr=0x7f80002050
              THREAD(10649):[12:14:56.155772] Free common=0x7f80002a30
              THREAD(10649):[12:14:56.155982] Jobq *FREE* report hdr/rpt 0x7f78000e50/0x7f78000e70 (data)
              THREAD(10649):[12:14:56.156188] Free report hdr=0x7f78000e70 reporter thread suspend count=618 packetring=0x7f78001b30 histo=(nil) frame histo=(nil)
              THREAD(10649):[12:14:56.156391] Free packet ring=0x7f78001b30 producer=0x7f80003e00 (consumer=0x5572491b50) awaits = 0 total rings = 0
              THREAD(10648):[12:14:56.156611] Free common=0x7f840017d0
              THREAD(10648):[12:14:56.156712] Server destructor sock=3 fullduplex=false
              THREAD(10648):[12:14:56.156805] Free thread settings=0x7f80001130
              THREAD(10650):[12:14:56.156895] Free thread settings=0x7f80004b70
              THREAD(10650):[12:14:56.156993] Signal sent to reporter thread
              THREAD(10648):[12:14:56.157088] Signal sent to reporter thread
              THREAD(10646):[12:14:56.157199] Jobq *WAIT* exit  (nil)/(nil) cond=0x5572491b50 threads u/t=3/1
              THREAD(10649):[12:14:56.159037] Free common=0x7f780017d0
              THREAD(10649):[12:14:56.159246] Server destructor sock=4 fullduplex=false
              THREAD(10649):[12:14:56.159388] Free thread settings=0x7f80003a70
              THREAD(10649):[12:14:56.159681] Signal sent to reporter thread
              THREAD(10646):[12:14:56.159906] Jobq *WAIT* exit  (nil)/(nil) cond=0x5572491b50 threads u/t=2/0
              THREAD(10646):[12:14:57.160102] Jobq *WAIT* exit  (nil)/(nil) cond=0x5572491b50 threads u/t=2/0
              THREAD(10646):[12:14:58.160336] Jobq *WAIT* exit  (nil)/(nil) cond=0x5572491b50 threads u/t=2/0
              
               

              Last edit: Robert McMahon 2023-09-06
              • Ryan Campbell

                Ryan Campbell - 2023-09-06

                It created about ~1000 sockets this time so from some investigation I believe the following happens:

                1. Listening socket binds to *:5001
                2. Client wants to connect to 192.168.0.102
                3. Listener calls udp_accept() where it calls connect(), but it binds the socket to 192.168.0.2
                4. Subsequent datagrams arrive on *:5001, and create more sockets

                Looking at the how the active table is called in udp_accept it would return true if the host was there but the port wasn't.

                Attached the thread-debug output because it filled the terminal.
                Only got the following - Killed it from another terminal

                [root@linux src]$ ./iperf -us > /tmp/output.txt
                socket failed (Listener.cpp:436): Too many open files (24)
                *** %n in writable segment detected ***
                
                ^C
                Killed
                
                 
                • Robert McMahon

                  Robert McMahon - 2023-09-06

                  yes, this is how it's supposed to work, only new sockets on new ip quintuples. But then this is a problem as the quintuples are the same yet new udp accepts occurred on the same quintuple.

                  [  2] local 192.168.0.2 port 5001 connected with 192.168.0.20 port 55538
                  [  3] local 192.168.0.2 port 5001 connected with 192.168.0.20 port 55538
                  [  4] local 192.168.0.2 port 5001 connected with 192.168.0.20 port 55538
                  [  5] local 192.168.0.2 port 5001 connected with 192.168.0.20 port 55538
                  [  6] local 192.168.0.2 port 5001 connected with 192.168.0.20 port 555
                  
                   

                  Last edit: Robert McMahon 2023-09-06
                  • Robert McMahon

                    Robert McMahon - 2023-09-06

                    This should stop the duplicates

                    /*
                    
                     * Check if the host and port are present in the active table
                     */
                    bool Iperf_host_port_present (iperf_sockaddr *find) {
                        Iperf_ListEntry *itr = active_table.root;
                        bool rc = false;
                        while (itr != NULL) {
                            if (SockAddr_are_Equal(&itr->host, find)) {
                    #if HAVE_THREAD_DEBUG
                            active_table_show_compare("match", itr, find, "client ip/port");
                    #endif
                            rc = true;
                                break;
                            } else {
                    #if HAVE_THREAD_DEBUG
                            active_table_show_compare("miss", itr, find, "client ip/port");
                    #endif
                            itr = itr->next;
                        }
                        }
                        return rc;
                    }
                    
                     
                    • Robert McMahon

                      Robert McMahon - 2023-09-06

                      udp accept checks the full quintuple per this

                          // Handle connection for UDP sockets
                          int gid = Iperf_push_host_port_conditional(server);
                      
                       
                      • Ryan Campbell

                        Ryan Campbell - 2023-09-06

                        In active_table_update() it will only add an entry if the host isn't present, otherwise it increases the thread count.

                        static void active_table_update (iperf_sockaddr *host, struct thread_Settings *agent) {
                            .........
                            Iperf_ListEntry *this_entry = Iperf_host_present(host);
                            active_table.total_count++;
                            if (this_entry == NULL) {
                            this_entry = new Iperf_ListEntry();
                            .....
                            } else {
                            this_entry->thread_count++;
                            ........
                            }
                        }
                        

                        ie if we received the following in this order to Iperf_push_host_port_conditional

                        1. 192.168.0.2:60000 added as an Iperf_ListEntry
                        2. 192.168.0.2:50000 thread count increased
                        3. 192.168.0.2:60000 skipped by Iperf_host_port_present
                        4. 192.168.0.2:50000 thread count increased again

                        So all subsequent connections would go through as when it increases thread count there is no tracking of which port it just created.

                        // Used for UDP push of a new host, returns negative value if the host/port is already present
                        // This is critical because UDP is connectionless and designed to be stateless
                        int Iperf_push_host_port_conditional (struct thread_Settings *agent) {
                            iperf_sockaddr *host = active_table_get_host_key(agent);
                            int rc = -1;
                            Mutex_Lock(&active_table.my_mutex);
                            if (!Iperf_host_port_present(host)) {
                            active_table_update(host, agent);
                            rc = active_table.groupid;
                            }
                            Mutex_Unlock(&active_table.my_mutex);
                            return (rc);
                        }
                        
                         

                        Last edit: Ryan Campbell 2023-09-06
                        • Robert McMahon

                          Robert McMahon - 2023-09-06

                          Hmm, that's not what I'm reading. I don't think iperf_push_host should ever be called for UDP only iperf_push_host_port_conditional. The output with --configure --enable-thread-debug would show it though.

                           

                          Last edit: Robert McMahon 2023-09-06
                          • Ryan Campbell

                            Ryan Campbell - 2023-09-06

                            Yeah it doesn't look like it's calling iperf_push_host, only the _conditional. I cut out the rest of the output above and kept only the first few 'active table' entries here. There's only 1 'new entry' in the file

                            THREAD(21941):[15:22:13.132447] active table: new entry 192.168.0.20 port 40308 (flag=1) rootp=0x7f4800001f40 entryp=0x7f4800001f40 totcnt/activecnt/hostcnt = 1/1/1
                            
                            THREAD(21941):[15:22:13.134193] active table: compare table entry client ip/port 192.168.0.20/40308 against host 192.168.0.20/53986 (miss)
                            THREAD(21941):[15:22:13.134210] active table: compare table entry client ip 192.168.0.20/40308 against host 192.168.0.20/53986 (match)
                            THREAD(21941):[15:22:13.134353] active table: incr entry 192.168.0.20 port 40308 (flag=1) rootp=0x7f4800001f40 entryp=0x7f4800001f40 totcnt/activecnt/hostcnt = 2/1/2
                            
                            THREAD(21941):[15:22:13.136049] active table: compare table entry client ip/port 192.168.0.20/40308 against host 192.168.0.20/53986 (miss)
                            THREAD(21941):[15:22:13.136063] active table: compare table entry client ip 192.168.0.20/40308 against host 192.168.0.20/53986 (match)
                            THREAD(21941):[15:22:13.136087] active table: incr entry 192.168.0.20 port 40308 (flag=1) rootp=0x7f
                            
                             
                            • Robert McMahon

                              Robert McMahon - 2023-09-06

                              There is only 1 new entry because the summing is per source ip and not source ip/port, so that's right. What I don't understand is all the connect messages for the same src ip/src port. Those seem wrong.

                               
                              • Robert McMahon

                                Robert McMahon - 2023-09-07

                                can you post the full output. Probably easiest to read it as a log and attachment if that can be done.

                                 
  • Robert McMahon

    Robert McMahon - 2023-09-07

    I see the problem and need to think about the best solution. The listener tread is receiving packets for the server thread per using recvmsg.

    A work around is to use port ranges on the server and incr-dstport on the client.

    root@raspberrypi:/usr/local/src/iperf2-code# src/iperf -s -u -p 5001-5004
    ------------------------------------------------------------
    Server listening on UDP ports 5001-5004 with pid 19933
    UDP buffer size:  208 KByte (default)
    ------------------------------------------------------------
    [  2] local 192.168.1.33 port 5003 connected with 192.168.1.32 port 52653
    [  3] local 192.168.1.33 port 5002 connected with 192.168.1.32 port 56930
    [  1] local 192.168.1.33 port 5001 connected with 192.168.1.32 port 56992
    
    
    root@raspberrypi:/usr/local/src/iperf2-code# src/iperf -uc 192.168.1.33  -b 50M -P 3 --incr-dstport -i 1
    ------------------------------------------------------------
    Client connecting to 192.168.1.33, UDP port 5001
    Sending 1470 byte datagrams, IPG target: 224.30 us (kalman adjust)
    UDP buffer size:  208 KByte (default)
    ------------------------------------------------------------
    [  3] local 192.168.1.32 port 52653 connected with 192.168.1.33 port 5003
    [  2] local 192.168.1.32 port 56930 connected with 192.168.1.33 port 5002
    [  1] local 192.168.1.32 port 56992 connected with 192.168.1.33 port 5001
    [ ID] Interval       Transfer     Bandwidth
    [  2] 0.00-1.00 sec  6.25 MBytes  52.4 Mbits/sec
    
     

    Last edit: Robert McMahon 2023-09-08
    • Ryan Campbell

      Ryan Campbell - 2023-09-08

      As a note I tried keeping the listener bound to *:5001 w/ the same socket and creating the server UDP sockets as needed but a large number of messages still made it to the listener.

      # netstat -an4 
      Active Internet connections (including servers)
      Proto Recv-Q Send-Q Local Address          Foreign Address        (state) 
      udp4       0      0 172.31.1.184.5001      *.*                    
      udp4   41608      0 172.31.1.184.5001      172.31.1.1.44488       
      udp4   40986      0 172.31.1.184.5001      172.31.1.1.56582       
      udp4   40986      0 172.31.1.184.5001      172.31.1.1.45141       
      udp4   36432      0 *.5001                 *.* 
      

      Top udp4 socket shouldn't have been made + 36 432 messages on the listening socket is not great

       
  • Robert McMahon

    Robert McMahon - 2023-09-08

    I think I found the bug. Can you try the latest as of Sept 8?

    [rjmcmahon@fedora iperf2-code]$ src/iperf -v
    iperf version 2.1.n (8 September 2023) pthreads

    Bob

     
    • Ryan Campbell

      Ryan Campbell - 2023-09-08

      Crashed again - attached output w/ enable-thread-debug

      $ src/iperf -uc 192.168.0.102 -P 3 -b 50M
      $ src/iperf -v
      iperf version 2.1.n (8 September 2023) pthreads
      .....
      [root@linux ~]$ ./iperf -us > /tmp/output-3aa566.txt
      socket failed (Listener.cpp:441): Too many open files (24)
      *** %n in writable segment detected ***
      Killed
      [root@linux ~]$ vi /tmp/output-3aa566.txt 
      [root@linux ~]$ ./iperf -v
      iperf version 2.1.n (8 September 2023) pthreads
      
       
      • Robert McMahon

        Robert McMahon - 2023-09-11

        Can you try the latest and provide the output again?

        [rjmcmahon@fedora iperf2-code]$ src/iperf -v
        iperf version 2.1.n (11 September 2023) pthreads
        
         
        • Ryan Campbell

          Ryan Campbell - 2023-09-14

          Tried latest and uploaded the output .
          It didn't create too many sockets, but it didn't destroy them or receive traffic.

          Note: I did realize that this only happens when the server's two NIC's have ip addresses that are on the same subnet, which is not an ideal configuration

          Another note, I had to cut the output at 20k lines as it wouldn't let me upload the whole 50 MB file. Cut from about 401K lines

          I assume this is because connect() knows both routes will reach the destination. so picks whichever it believes is best

          $ src/iperf -v
          iperf version 2.1.n (11 September 2023) pthreads
          
          [root@linux ~]$ ss -nu // first run
          Local Address:Port            Peer Address:Port 
            192.168.0.2:5001              192.168.0.20:59385
            192.168.0.2:5001              192.168.0.20:60080
            192.168.0.2:5001              192.168.0.20:49522
            192.168.0.2:5001              192.168.0.20:44084
            192.168.0.2:5001              192.168.0.20:57140
            192.168.0.2:5001              192.168.0.20:54360
          [root@linux ~]$ ss -nu // second run
          Local Address:Port            Peer Address:Port 
            192.168.0.2:5001              192.168.0.20:41241
            192.168.0.2:5001              192.168.0.20:59721
            192.168.0.2:5001              192.168.0.20:40834
            192.168.0.2:5001              192.168.0.20:59385
            192.168.0.2:5001              192.168.0.20:60080
            192.168.0.2:5001              192.168.0.20:49522
            192.168.0.2:5001              192.168.0.20:44084
            192.168.0.2:5001              192.168.0.20:57140
            192.168.0.2:5001              192.168.0.20:5436
          
           
          • Robert McMahon

            Robert McMahon - 2023-09-14

            what happens when you compile without --enable-thread-debug? The new code should drop the duplicate flows but new flows should work.

            Also, is this linux? Can you share the output of uname -r to get the kernel version? Most systems won't send the same flow to two different threads after a connect.

             
1 2 > >> (Page 1 of 2)

Log in to post a comment.