Higher latency calculation (using time and sent_time)

[kpetremann]

EDIT AS OF 05/09/20: Scapy > 2.4.4 fixes this issue. See #2277

Brief description

Since 2.4.1 version of scapy, latency reported is 10 times higher than 2.4.0.

Environment

• Scapy version: Scapy 2.4.0
• Python version: 3.4.5
• Operating System: centos 7.4

How to reproduce

Destination is internal servers running on Datacenter. So traffic is intra DC.

dest = "10.0.0.1"

pkt = []
for i in range(1,50):
    a = IP(dst=dest) / TCP(flags="S", seq=i, sport=65000, dport=55556)
    pkt.append(a)

ans, unans = sr(pkt, filter="host {0}".format(dest), inter=0, timeout=1)

print("scapy version: {}".format(conf.version))

for pkt in ans:
    sent = pkt[0]
    received = pkt[1]
    res = (received.time - sent.sent_time) * 1000
    print(res)

Actual result

The target is at less than 1ms of latency. Reported the same for traffic between datacenters in different countries.

Example of results in scapy 2.4.0:

Begin emission:
*********************************Finished sending 49 packets.
****************
Received 49 packets, got 49 answers, remaining 0 packets
scapy version: 2.4.0
4.350900650024414
0.2079010009765625
0.1971721649169922
0.2334117889404297
0.1659393310546875
0.20956993103027344
0.21123886108398438
0.19788742065429688
0.15878677368164062
0.15211105346679688
0.15401840209960938
0.16045570373535156
0.15544891357421875
0.14519691467285156
0.14662742614746094
0.15163421630859375
0.14638900756835938
0.1544952392578125
0.1499652862548828
0.1659393310546875
0.15854835510253906
0.18978118896484375
0.2117156982421875
0.1952648162841797
0.1842975616455078
0.18072128295898438
0.15878677368164062
0.1537799835205078
0.19860267639160156
0.16117095947265625
0.1442432403564453
0.14972686767578125
0.19240379333496094
0.20503997802734375
0.16236305236816406
0.1850128173828125
0.16832351684570312
0.19311904907226562
0.1888275146484375
0.17499923706054688
0.14281272888183594
0.15091896057128906
0.1442432403564453
0.22530555725097656
0.2033710479736328
0.2231597900390625
0.20885467529296875
0.23102760314941406
0.1971721649169922

Example of results in scapy 2.4.2:

Begin emission:
************************************Finished sending 49 packets.
*************
Received 49 packets, got 49 answers, remaining 0 packets
scapy version: 2.4.2
5.141973495483398
4.551172256469727
5.909204483032227
4.38380241394043
8.071660995483398
8.111000061035156
10.76817512512207
11.934280395507812
11.676311492919922
14.704227447509766
15.71202278137207
15.697956085205078
16.704320907592773
15.500307083129883
15.828371047973633
17.41957664489746
17.516613006591797
16.1285400390625
17.355918884277344
17.473220825195312
19.101381301879883
20.766496658325195
19.442319869995117
18.988847732543945
19.248485565185547
19.159793853759766
20.247936248779297
21.417856216430664
23.09250831604004
25.787830352783203
27.456998825073242
28.298139572143555
29.371976852416992
29.3734073638916
29.6783447265625
29.912233352661133
29.05869483947754
28.344154357910156
26.66330337524414
25.910377502441406
24.534940719604492
23.717164993286133
22.020816802978516
21.22044563293457
19.37270164489746
17.622709274291992
15.846014022827148
13.768911361694336
11.74163818359375

[guedou]

Please follow the template while opening an issue. You removed a lot of useful information.

I tried your code on v2.4.0 and v2.4.2 and did not find any difference.

[kpetremann]

hello @guedou . Thanks for the quick response.

Sorry for the template, I have updated the summary using it, and updating results/scripts.

FYI, I am running a program using scapy to generate metrics (latency/loss) across multiple datacenter. And I noticed this latency increase since 2.4.2. When I rolled back to 2.4.0, the issue disappeared.

[kpetremann]

The issue is more visible when source and destination are closed to each other (same datacenter).

I have tested on another bunch of servers and I see:
0.095367431640625 via scapy 2.4.0
3.555774688720703 via scapy 2.4.2

Also, I have graphs showing this:

The higher latency was using 2.4.2, and before and after it was 2.4.0

[kpetremann]

I reproduce also the issue from a Manjaro linux (kernel 4.19.13-1) to an Arch Linux using Python 3.7.2.

Received 50 packets, got 49 answers, remaining 0 packets
scapy version: 2.4.2
4.761457443237305
8.883953094482422
6.258249282836914
7.727384567260742
6.662845611572266
6.570577621459961
3.8030147552490234
2.572298049926758
5.140542984008789


scapy version: 2.4.0
0.17404556274414062
0.186920166015625
0.19741058349609375
0.15020370483398438
0.24366378784179688
0.1494884490966797
0.2148151397705078
0.18906593322753906
0.18525123596191406
0.17404556274414062

[guedou]

Thanks for the updated report! That will help us investigate the issue.

[gpotter2]

I only see #1142 as potential root of the issue.

I think I got it, will PR a fix soon

[gpotter2]

@kpetremann Hi ! Could you check that #1847 fixes your issue ? Thanks !

[kpetremann]

@gpotter2 sure I'll try it and will let you know. Thanks!

[gpotter2]

Thanks !It’s still a bit unstable though :/

[kpetremann]

@gpotter2 > does not seem to improve measurement according my quick test:

• green: scapy 2.4.0
• yellow: code from Fix various memory leaks when receiving packets #1847

[gpotter2]

Thanks, I’ll try stuff and get back to you.

[gpotter2]

@guedou @p-l- Any help will be greatly appreciated :/ I can’t find what happened that slowed the tests that much...

A quick way to reproduce is to use the latency test in test/benchmarks/, on master and on tags/v2.4.0