search

deajan / tcpping

tcpping script for smokeping that runs with newer linux traceroute binaries
GNU General Public License v3.0
127 stars 39 forks source link

Tcpping reporting "no response (timeout)" for extended time #17

Closed docast closed 1 month ago

docast commented 8 months ago

Hi Team,

As per the below tcpping results output, the tcpping tool reported "no sequence timeout" errors from "Wed Jan 31 04:58:19 UTC 2024" till "Wed Jan 31 04:59:02 UTC 2024" between client and server VM for about 45 seconds. The tcpping test is executed every second with parameter "-r 1".

When we checked with the cloud provider, there was a NIC update on the node hosting the tcpping server VM. However, the Nic update had completed in less than 10 seconds and was within the SLA. From linux kernal logs we also see that the Vf registration of the NIC had completed in less than 10 seconds. However, the tcpping tool reported " no sequence timeouts" for close to 45 seconds.

Ask:

  1. Why did the tcpping tool report " no sequence timeout" for 45 seconds, though the underlying NIC had re-registered back in 10 seconds after NIC update? I was expecting the "no sequence timeouts" only for 10 seconds and not for 45 seconds? Why the tcpping tool is taking more time to recover after the NIC update? After 45 seconds, the tcpping stated to work fine reporting latency between client and server VM:
  2. Is there some caching in connection that's causing this problem? If yes, is there a way to reset the cache before executing the tcpping test that's executed every second?

Here is the tcpping output snippet which reported no sequence timeouts for 45 seconds:

Wed Jan 31 04:58:12 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 115: tcp response from 10.10.1.23 (10.10.1.23) <syn,ack> 1.417 ms Wed Jan 31 04:58:13 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 116: tcp response from 10.10.1.23 (10.10.1.23) <syn,ack> 1.485 ms Wed Jan 31 04:58:14 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 117: tcp response from 10.10.1.23 (10.10.1.23) <syn,ack> 1.109 ms Wed Jan 31 04:58:15 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 118: tcp response from 10.10.1.23 (10.10.1.23) <syn,ack> 1.050 ms Wed Jan 31 04:58:16 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 119: tcp response from 10.10.1.23 (10.10.1.23) <syn,ack> 1.118 ms Wed Jan 31 04:58:17 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 120: tcp response from 10.10.1.23 (10.10.1.23) <syn,ack> 1.245 ms Wed Jan 31 04:58:18 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 121: tcp response from 10.10.1.23 (10.10.1.23) <syn,ack> 0.989 ms Wed Jan 31 04:58:19 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 122: no response (timeout) Wed Jan 31 04:58:20 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 123: no response (timeout) Wed Jan 31 04:58:21 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 124: no response (timeout) Wed Jan 31 04:58:22 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 125: no response (timeout) Wed Jan 31 04:58:23 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 126: no response (timeout) Wed Jan 31 04:58:24 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 127: no response (timeout) Wed Jan 31 04:58:25 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 128: no response (timeout) Wed Jan 31 04:58:26 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 129: no response (timeout) Wed Jan 31 04:58:27 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 130: no response (timeout) Wed Jan 31 04:58:28 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 131: no response (timeout) Wed Jan 31 04:58:29 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 132: no response (timeout) Wed Jan 31 04:58:30 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 133: no response (timeout) Wed Jan 31 04:58:31 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 134: no response (timeout) Wed Jan 31 04:58:32 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 135: no response (timeout) Wed Jan 31 04:58:33 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 136: no response (timeout) Wed Jan 31 04:58:34 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 137: no response (timeout) Wed Jan 31 04:58:35 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 138: no response (timeout) Wed Jan 31 04:58:36 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 139: no response (timeout) Wed Jan 31 04:58:37 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 140: no response (timeout) Wed Jan 31 04:58:38 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 141: no response (timeout) Wed Jan 31 04:58:39 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 142: no response (timeout) Wed Jan 31 04:58:40 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 143: no response (timeout) Wed Jan 31 04:58:41 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 144: no response (timeout) Wed Jan 31 04:58:42 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 145: no response (timeout) Wed Jan 31 04:58:43 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 146: no response (timeout) Wed Jan 31 04:58:44 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 147: no response (timeout) Wed Jan 31 04:58:45 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 148: no response (timeout) Wed Jan 31 04:58:46 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 149: no response (timeout) Wed Jan 31 04:58:47 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 150: no response (timeout) Wed Jan 31 04:58:48 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 151: no response (timeout) Wed Jan 31 04:58:49 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 152: no response (timeout) Wed Jan 31 04:58:50 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 153: no response (timeout) Wed Jan 31 04:58:51 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 154: no response (timeout) Wed Jan 31 04:58:52 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 155: no response (timeout) Wed Jan 31 04:58:53 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 156: no response (timeout) Wed Jan 31 04:58:54 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 157: no response (timeout) Wed Jan 31 04:58:55 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 158: no response (timeout) Wed Jan 31 04:58:56 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 159: no response (timeout) Wed Jan 31 04:58:57 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 160: no response (timeout) Wed Jan 31 04:58:58 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 161: no response (timeout) Wed Jan 31 04:58:59 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 162: no response (timeout) Wed Jan 31 04:59:02 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 165: tcp response from 10.10.1.23 (10.10.1.23) <syn,ack> 0.862 ms Wed Jan 31 04:59:00 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 163: no response (timeout) Wed Jan 31 04:59:03 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 166: tcp response from 10.10.1.23 (10.10.1.23) <syn,ack> 0.916 ms Wed Jan 31 04:59:01 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 164: no response (timeout) Wed Jan 31 04:59:04 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 167: tcp response from 10.10.1.23 (10.10.1.23) <syn,ack> 1.102 ms Wed Jan 31 04:59:05 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 168: tcp response from 10.10.1.23 (10.10.1.23) <syn,ack> 1.165 ms Wed Jan 31 04:59:06 UTC 2024 traceroute to 10.10.1.23 (10.10.1.23), 255 hops max, 60 byte packets seq 169: tcp response from 10.10.1.23 (10.10.1.23) <syn,ack> 0.893 ms

docast commented 7 months ago

@deajan any update on the above ?

deajan commented 7 months ago

So that's quite a broad question, since there isn't a simple reproducer. tcping uses traceroute as underlying tcp/udp/icmp ping implementation, and does not cache anything by itself.

So the problem would come from traceroute, which IMHO shouldn't cache anything neither.

You can obtain the traceroute command used by using _DEBUG=true tcpping host port.

deajan commented 1 month ago

After some tests, it seems that the problem is not tcpping related but rather traceroute.