Higher or negative latency using 2.4.3 (time - sent_time)

[kpetremann]

Brief description

Latency calculated is 10 times higher than 2.4.0, and sometimes, latency is negative.

Looks like #1791 but with negative values now.

The test is done in TCP.

It does not seem there is a mismatch between receive and sent packets as SEQ/ACK and SPORT/DPORT matches.

Environment

Scapy version: Scapy 2.4.3
Python version: 3.6 & 3.7
Operating System: centos 7.4 & arch linux

Tests are done in a LAN with stable machine, and also in production in datacenters.

How to reproduce

dest = "192.168.0.1"

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

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

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)
    if res < 0:
        breakpoint()

Actual result

Using 2.4.0:

Begin emission:
.****************************************************Finished sending 99 packets.
***********************************************
Received 100 packets, got 99 answers, remaining 0 packets
...................................................................................................
Sent 99 packets.
scapy version: 2.4.0
0.48351287841796875
0.31113624572753906
0.46896934509277344
....
0.27561187744140625
0.3025531768798828
0.38909912109375
0.3840923309326172
0.3809928894042969
0.2892017364501953

Using 2.4.3:

sudo python ./test.py
Begin emission:
.**************************************************************************************************Finished sending 99 packets.
*
Received 100 packets, got 99 answers, remaining 0 packets
...................................................................................................
Sent 99 packets.
scapy version: 2.4.3
3.6242008209228516
2.803325653076172
3.2286643981933594
7.400989532470703
12.633323669433594
13.63062858581543
15.126228332519531
11.01994514465332
24.735450744628906
24.316787719726562
23.879051208496094
23.487329483032227
22.953510284423828
22.533655166625977
22.108078002929688
40.10128974914551
39.75367546081543
39.3528938293457
38.92111778259277
38.49363327026367
38.06662559509277
37.683963775634766
36.977529525756836
36.301374435424805
34.806013107299805
34.380197525024414
34.37399864196777
34.02996063232422
33.62083435058594
33.17570686340332
32.75179862976074
32.33003616333008
24.41573143005371
23.94843101501465
23.525714874267578
23.09560775756836
22.677898406982422
22.095203399658203
21.67963981628418
21.364927291870117
20.95651626586914
20.496606826782227
20.053863525390625
19.638776779174805
19.222021102905273
18.764257431030273
18.578290939331055
18.302440643310547
19.684314727783203
...
-0.3478527069091797
[0] > /home/kevin/tmp/scapy-test/test.py(18)<module>()
-> for pkt in ans:
(Pdb++) sent
<IP  frag=0 proto=tcp dst=192.168.18.71 |<TCP  sport=65067 dport=55556 seq=67 flags=S |>>
(Pdb++) received
<IP  version=4 ihl=5 tos=0x0 len=40 id=0 flags=DF frag=0 ttl=64 proto=tcp chksum=0x94e4 src=192.168.18.71 dst=192.168.18.84 |<TCP  sport=55556 dport=65067 seq=0 ack=68 dataofs=5 reserved=0 flags=RA window=0 chksum=0x3270 urgptr=0 |<Padding  load='\x00\x00\x00\x00\x00\x00' |>>>

[gpotter2]

Hi, @kpetremann sorry for the delay.

Could you try out https://github.com/gpotter2/scapy/tree/cleanups ? (With Python 3 so that it uses ancillary data).

On my end this reduces localhost pings x20 on average, fixed the negative latency and produced much more accurate results. It might not fix the issue, please have a look.

Thanks !

[kpetremann]

Hi @gpotter2, no problem.

I have tested using python 3.6 and 3.8. I don't have negative results anymore but unfortunately still too high latency reported:

scapy version: 2.3.3.dev2775
93.66059303283691
91.20345115661621
88.85693550109863
86.55905723571777
84.29694175720215
82.05008506774902
...
27.074575424194336
26.698589324951172
26.328563690185547

2.4.0 is still reporting 0.30 in average.

[gpotter2]

2.3.3.dev2775

? That seems weird

[kpetremann]

2.3.3.dev2775

? That seems weird

I saw it, but even when I run ./run_scapy from the cleanups branch I have this version indicated.

git remote -v                 
origin	https://github.com/gpotter2/scapy.git (fetch)

git branch -v
* cleanups feccad02 Rework timestamp detection

git log --oneline
feccad02 (HEAD -> cleanups, origin/cleanups) Rework timestamp detection
9c7961ca Merge pull request #2388 from guedou/PR#2386_fixed
d38dcb79 Spelling error fixed
61cd7c82 start of refactoring and improvement of automotive documentation
1b501c61 Merge pull request #2376 from gpotter2/cleanups
9504c4bd Make dissection_and_build.py work on Windows
63e145e4 Merge pull request #2378 from guedou/PR#2135_improved
...

./run_scapy
... Version 2.3.3.dev2775

Have I done something wrong?

[gpotter2]

In all honesty I can't reproduce getting such bad timestamps. Here's what I use (I use ARP instead of TCP pings because firewalls)

from scapy.all import *
dest = "10.0.0.1"

pkt = []
for i in range(1, 100):
    a = Ether(dst="ff:ff:ff:ff:ff:ff") / ARP(pdst=dest)
    pkt.append(a)

ans, unans = srp(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)
    if res <  0:
        breakpoint()

Results are nowhere as bad:

Begin emission:
**************************************************************************************************Finished sending 99 packets.
*
Received 99 packets, got 99 answers, remaining 0 packetsscapy version: 2.4.3rc3.dev223
0.44155120849609375
0.6132125854492188
0.19621849060058594
0.33402442932128906
0.23889541625976562
0.30875205993652344
0.19216537475585938
0.27298927307128906
0.3032684326171875
0.2601146697998047
0.2875328063964844
0.2713203430175781
0.2791881561279297
0.4181861877441406
0.3693103790283203
0.2675056457519531
0.33736228942871094
0.32711029052734375
0.5595684051513672
0.247955322265625
0.22649765014648438
0.31447410583496094
0.35381317138671875
0.22602081298828125
0.3781318664550781
0.40030479431152344
0.32138824462890625
0.23746490478515625
0.32782554626464844
0.3268718719482422
0.19693374633789062
0.16236305236816406
0.39315223693847656
0.4329681396484375
0.2732276916503906
0.4172325134277344
0.19669532775878906
0.27489662170410156
0.2307891845703125
0.7529258728027344
0.6041526794433594
0.3712177276611328
0.21028518676757812
0.18334388732910156
0.20956993103027344
0.1900196075439453
0.3273487091064453
0.30732154846191406
0.2143383026123047
0.2677440643310547
0.2129077911376953
0.3285408020019531
0.4177093505859375
0.22029876708984375
0.4780292510986328
0.5998611450195312
0.21910667419433594
0.29397010803222656
0.29015541076660156
0.29277801513671875
0.3592967987060547
0.25200843811035156
0.1659393310546875
0.18715858459472656
0.3185272216796875
0.2818107604980469
0.19311904907226562
0.4012584686279297
0.30732154846191406
0.2856254577636719
0.4673004150390625
0.6401538848876953
0.22983551025390625
0.19812583923339844
0.2033710479736328
0.23627281188964844
0.5517005920410156
0.21529197692871094
0.33402442932128906
0.2930164337158203
0.2791881561279297
0.4057884216308594
0.2453327178955078
0.2491474151611328
0.30875205993652344
0.2884864807128906
0.2932548522949219
0.26226043701171875
0.2665519714355469
0.20575523376464844
0.31948089599609375
0.5686283111572266
0.293731689453125
0.22983551025390625
0.5993843078613281
0.2677440643310547
0.2956390380859375
0.37670135498046875
0.3077983856201172

[gpotter2]

It's fine, as long as you're using the correct version. Tags aren't updated when fetching, you might need to do
git fetch upstream --prune-tags
Or similar

[kpetremann]

ok, I've run another test on servers in preproduction (previously it was on my desktop). There are running python3.6.

I am targeting a server in the same rack, same vlan.

Using your script in ARP, I have the same results than you!

scapy version: 2.3.3.dev2775
0.02002716064453125
0.02288818359375
0.019073486328125
0.019311904907226562

scapy version: 2.4.0
0.021696090698242188
0.020742416381835938
0.024080276489257812
0.02002716064453125

However, running my script (so using TCP instead of ARP) I have differences:

scapy version: 2.3.3.dev2775
69.96822357177734
69.40793991088867
68.98093223571777
68.55320930480957
68.01509857177734

scapy version: 2.4.0
0.09250640869140625
0.125885009765625
0.08559226989746094
0.12755393981933594

I am also doing probing using ICMP and UDP on a closed port (waiting for an ICMP response). I'll check if this the same behaviour (I think so because I use the time at IP layer).

[gpotter2]

Thanks for the examples, I'll try to figure out what happens with TCP.

The cleanups branch especially improves localhost ping: using your TCP example with 127.0.0.1 and conf.L3socket=L3RawSocket, it benefits from a ~ x20 speedup.

[gpotter2]

Hi @kpetremann,
Could you try out #2426

[kpetremann]

hi @gpotter2, looks very good according my test script!
I'll run it in preprod in my app today and will let you know about the results at scale

[gpotter2]

Hi, did you have a chance to look at it?