#266 Regression in --txstart-time

[Robert McMahon]

Hi Bob,

With new iperf we see client connecting starts after specified txstart time 
16:29:30.177  LOG   10.123.6.191       iperf -v
16:29:30.211  LOG   10.123.6.191       iperf version 2.1.n (5 June 2023) pthreads


16:19:21.271  DEBUG IPERFCMD                               iperf -c 192.168.1.195 -e -w 24M -B 192.168.1.218 --bounceback --bounceback-hold 0 --bounceback-period 1  --hide-ips -l 100 --trip-times --txstart-time 1687862969 -i 1 -fb -S 0x00 -T 255 -t 30 -p 61001 --trip-times --histogram
16:19:21.272  INFO  r6726_5G_TAG_LLAPI-4398_STA1-DOWN-1-tx calling rpopen: iperf -c 192.168.1.195 -e -w 24M -B 192.168.1.218 --bounceback --bounceback-hold 0 --bounceback-period 1  --hide-ips -l 100 --trip-times --txstart-time 1687862969 -i 1 -fb -S 0x00 -T 255 -t 30 -p 61001 --trip-times --histogram
16:19:21.273  LOG   10.123.6.191                           iperf -c 192.168.1.195 -e -w 24M -B 192.168.1.218 --bounceback --bounceback-hold 0 --bounceback-period 1  --hide-ips -l 100 --trip-times --txstart-time 1687862969 -i 1 -fb -S 0x00 -T 255 -t 30 -p 61001 --trip-times --histogram
16:19:21.284  VWAIT r6726_5G_TAG_LLAPI-4398_STA1-DOWN-1-tx vwait on READY : state is INIT 
16:19:21.300  LOG   4916>                                  CONSOLE[wl0]: 402510.644 wl0: wlc_iovar_ext: dump_clear: BCME -23
16:19:23.518  LOG   10.123.6.195>                          CONSOLE_E:1:489 4100.201476375 noise_cal_info: scan core: params: 0 1e c8,caller: 163647
16:19:23.520  LOG   10.123.6.195>                          CONSOLE_E:1:490 4100.203003029 noise_cal_info: scan core: params: 0 1e c8,caller: 163647
16:19:24.284  ERROR r6726_5G_TAG_LLAPI-4398_STA1-DOWN-1-tx iperf tx start timeout

In streams lib we look streams successfully connected using "regexp {^Client connecting to} $buf". Observe timeout issue  in streams lib with new iperf as client connecting starts after specified txstart time. 

With old iperf we see client connecting once we trigger the iperf client. But data transfer starts only after "txstart start time specified" 
[root@bca14end1 ~]# iperf8m --v
iperf version 2.1.n (8 March 2023) pthreads


16:29:38.789  DEBUG IPERFCMD                               iperf8m -c 192.168.1.195 -e -w 24M -B 192.168.1.218 --bounceback --bounceback-hold 0 --bounceback-period 1  --hide-ips -l 100 --trip-times --txstart-time 1687863586 -i 1 -fb -S 0x00 -T 255 -t 30 -p 61001 --trip-times --histogram
16:29:38.789  INFO  r6726_5G_TAG_LLAPI-4398_STA1-DOWN-1-tx calling rpopen: iperf8m -c 192.168.1.195 -e -w 24M -B 192.168.1.218 --bounceback --bounceback-hold 0 --bounceback-period 1  --hide-ips -l 100 --trip-times --txstart-time 1687863586 -i 1 -fb -S 0x00 -T 255 -t 30 -p 61001 --trip-times --histogram
16:29:38.791  LOG   10.123.6.191                           iperf8m -c 192.168.1.195 -e -w 24M -B 192.168.1.218 --bounceback --bounceback-hold 0 --bounceback-period 1  --hide-ips -l 100 --trip-times --txstart-time 1687863586 -i 1 -fb -S 0x00 -T 255 -t 30 -p 61001 --trip-times --histogram
16:29:38.800  VWAIT r6726_5G_TAG_LLAPI-4398_STA1-DOWN-1-tx vwait on READY : state is INIT 
16:29:38.801  LOG   4916>                                  CONSOLE[wl0]: 403128.385 wl0: wlc_iovar_ext: dump_clear: BCME -23
16:29:38.812  HNDLR r6726_5G_TAG_LLAPI-4398_STA1-DOWN-1-tx ------------------------------------------------------------ (lan,file18)
16:29:38.813  HNDLR r6726_5G_TAG_LLAPI-4398_STA1-DOWN-1-tx Client connecting to (**hidden**), TCP port 61001 with pid 12806 (1 flows) (lan,file18)
16:29:38.813  HNDLR r6726_5G_TAG_LLAPI-4398_STA1-DOWN-1-tx Handler now SAMPLING (lan,file18)
16:29:38.813  VWAIT r6726_5G_TAG_LLAPI-4398_STA1-DOWN-1-tx vwait DONE : state is READY 

Regards,
Guru

[Robert McMahon]

It looks like a regression. Let me check into it. The design was not to delay the TCP 3WHS (connect) but only delay the data xfer phase by the --txstart-time.