Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Scapy receives only first 150 replies when the native super sockets are in use #4531

Closed
GD1200 opened this issue Sep 13, 2024 · 17 comments
Closed
Labels
bug major Major changes

Comments

@GD1200
Copy link

GD1200 commented Sep 13, 2024

Brief description

When default native super sockets are used in Linux, Scapy receives only first 150 answers while packet dump confirms that no drops take place. The problem gets solved when libpcap sockets are activated. For example:

>>> conf.version
'2.6.0rc2.dev2'

>>> conf.use_pcap
False

>>> sr(IP(dst='192.168.168.2')/ICMP(seq=(1,1000)), timeout=1)
Begin emission:
Finished sending 1000 packets.
.*************************************************************************************************************************************************
Received 146 packets, got 145 answers, remaining 855 packets
(<Results: TCP:0 UDP:0 ICMP:145 Other:0>, <Unanswered: TCP:0 UDP:0 ICMP:855 Other:0>)


>>> conf.use_pcap = True

>>> conf.use_pcap
True

>>> sr(IP(dst='192.168.168.2')/ICMP(seq=(1,1000)), timeout=1)
Begin emission:
Finished sending 1000 packets.
*******************************************************************************************************************************************************************************************
*******************************************************************************************************************************************************************************************
*******************************************************************************************************************************************************************************************
*******************************************************************************************************************************************************************************************
*******************************************************************************************************************************************************************************************
*****************************************************************
Received 1000 packets, got 1000 answers, remaining 0 packets
(<Results: TCP:0 UDP:0 ICMP:1000 Other:0>, <Unanswered: TCP:0 UDP:0 ICMP:0 Other:0>)

The problem is reproducible with both the latest stable version 2.5.0 and the development one 2.6.0rc2.dev2.

To replicate the problem, I used the following local Linux setup:

# Create a dedicated network name space to simulate remote host
sudo ip netns add scapy

# Create a virtual Ethernet pair to connect default and new NS
sudo ip link add type veth

# Move veth1 to the new NS
sudo ip link set veth1 netns scapy

# Setup vNIC in the default NS
sudo ip link set veth0 up
sudo ip addr add 192.168.168.1/24 dev veth0

# Setup vNIC in the dedicated NS
sudo ip netns exec scapy ip link set lo up
sudo ip netns exec scapy ip link set veth1 up
sudo ip netns exec scapy ip addr add 192.168.168.2/24 dev veth1

# Verify IP reachability
sudo ping -i 0.001 -c 1000 -q 192.168.168.2
PING 192.168.168.2 (192.168.168.2) 56(84) bytes of data.

--- 192.168.168.2 ping statistics ---
1000 packets transmitted, 1000 received, 0% packet loss, time 999ms
rtt min/avg/max/mdev = 0.001/0.002/0.031/0.001 ms

The icmp.pcap.gz dump contains 2000 packets collected while sr() was executed against native super sockets.

Thank you.

Scapy version

2.6.0rc2.dev2

Python version

3.12.5

Operating system

Linux 6.10.6

@GD1200 GD1200 changed the title Scapy receives only 15% of replies when the native super sockets are in use Scapy receives only first 150 replies when the native super sockets are in use Sep 13, 2024
@GD1200
Copy link
Author

GD1200 commented Sep 14, 2024

As far as I can see, the problem was first introduced with commit 53afe84a (2.4.3rc1.dev32):

commit 53afe84ad586259a0bdc2e76b380259043bc46a9 (HEAD)
Author: gpotter2
Date:   Thu Feb 14 21:35:22 2019 +0100

    Fix latency scapy 2.4.2

This can be proved with the following method:

$ docker run --rm -it --privileged python:3.6-slim bash

# apt-get update && apt-get install -y git
# git clone https://github.com/secdev/scapy.git
# cd scapy & git checkout 53afe84a


# pip install .
# scapy

>>> conf.version
'2.4.3rc1.dev32'

>>> sr(IP(dst='172.17.0.1')/ICMP(seq=(1,1000)), timeout=1)
Begin emission:
Finished sending 1000 packets.
.******************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************
Received 475 packets, got 474 answers, remaining 525 packets
(<Results: TCP:0 UDP:0 ICMP:474 Other:0>, <Unanswered: TCP:0 UDP:0 ICMP:526 Other:0>)

When the 1-commit-before version is installed (2.4.3rc1.dev31), the problem is not manifested:

# git checkout 53afe84a~
Previous HEAD position was 53afe84a Fix latency scapy 2.4.2
HEAD is now at 75e1f457 Fix ttl setting in IGMP.igmpize()


# pip install .
# scapy

>>> conf.version
'2.4.3rc1.dev31'

>>> sr(IP(dst='172.17.0.1')/ICMP(seq=(1,1000)), timeout=1)
Begin emission:
***************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************Finished sending 1000 packets.

Received 999 packets, got 999 answers, remaining 0 packets
(<Results: TCP:0 UDP:0 ICMP:999 Other:0>, <Unanswered: TCP:0 UDP:0 ICMP:1 Other:0>)

It is worth mentioning, that 53afe84a introduced the problem, but the it got worse later. I still need to perform more tests to find out the second commit.

@gpotter2
Copy link
Member

You're right that's ugly. I'm however unsure of what's happening here.
This will likely require some thorough analysis

@GD1200
Copy link
Author

GD1200 commented Sep 14, 2024

The problem gets worse with the following commit:

commit 90c8d82070a9edaf0bbfe53b00db8dcf13154eed (HEAD)
Merge: d38f4bc2 f7c8e266
Author: Pierre Lalet <pierre@droids-corp.org>
Date:   Sun Jan 19 19:50:23 2020 +0100

    Merge pull request #2401 from gpotter2/cleanups

    Rework timestamp detection

Below is the output showing that after commit 90c8d820, Scapy can receive only 147 first packets:

# git checkout 90c8d820
HEAD is now at 90c8d820 Merge pull request #2401 from gpotter2/cleanups

# pip install .
...
Successfully installed scapy-2.4.3.dev237


>>> conf.version
'2.4.3.dev237'

>>> sr(IP(dst='172.17.0.1')/ICMP(seq=(1,1000)), timeout=1)
Begin emission:
Finished sending 1000 packets.
***************************************************************************************************************************************************
Received 147 packets, got 147 answers, remaining 853 packets
(<Results: TCP:0 UDP:0 ICMP:147 Other:0>, <Unanswered: TCP:0 UDP:0 ICMP:853 Other:0>)

If we go one commit back, we get into a bad situation, when only 600-700 first replies are received: the effect of the previously mentioned commit 53afe84a.

# git checkout 90c8d820~
Previous HEAD position was 90c8d820 Merge pull request #2401 from gpotter2/cleanups
HEAD is now at d38f4bc2 Merge pull request #2420 from gpotter2/testsstable

# pip install .
...
Successfully installed scapy-2.4.3.dev233


>>> conf.version
'2.4.3.dev233'


>>> sr(IP(dst='172.17.0.1')/ICMP(seq=(1,1000)), timeout=1)
Begin emission:
******************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************Finished sending 1000 packets.

Received 714 packets, got 714 answers, remaining 286 packets
(<Results: TCP:0 UDP:0 ICMP:714 Other:0>, <Unanswered: TCP:0 UDP:0 ICMP:286 Other:0>)

@polybassa
Copy link
Contributor

Thanks for your issue. Could you please check, if you receive more packets, if you increase the timeout.

I would like to understand, if the packets are "at least" in the kernels socket and scapy (python) just hadn't enough time to read them (maybe because of some slowness in sr)

LibPCAP uses PACKET_MMAP internally, afaik. This might reduce the number of syscalls to the kernel quite alot.

@GD1200
Copy link
Author

GD1200 commented Sep 14, 2024

Right, @polybassa, I forgot to mention that changing the timeout does not have any effect. For example, I get the same results even if timeout is one minute:

# uname -r
6.10.6-arch1-1

# python --version
Python 3.12.6

>>> conf.version
'2.6.0rc2.dev2'

>>> sr(IP(dst='172.17.0.1')/ICMP(seq=(1,1000)), timeout=60)
Begin emission:
Finished sending 1000 packets.
.*************************************************************************************************************************************************.
Received 147 packets, got 145 answers, remaining 855 packets
(<Results: TCP:0 UDP:0 ICMP:145 Other:0>, <Unanswered: TCP:0 UDP:0 ICMP:855 Other:0>)

@GD1200
Copy link
Author

GD1200 commented Sep 14, 2024

The problem gets worse with the following commit

To be more precise, the second regression happened at commit 0fa7d3f (2.4.3.dev227):

commit 0fa7d3f0d8acecc6aac046ae1bf8d6c0f428a441
Author: gpotter2
Date:   Fri Dec 27 14:49:43 2019 +0000

    Rework timestamp detection

To summarise, with my kernel 6.10.6, I observe the following:

  • before 53afe84 (2.4.3rc1.dev32): 1k of 1k replies are received
  • at 53afe84 (2.4.3rc1.dev32): only first 500-700 replies of 1k are received
  • starting with 0fa7d3f (2.4.3.dev227): only first 150 replies of 1k are received

@polybassa
Copy link
Contributor

I quickly looked into it.

I can confirm the issue on my system. I'm receiving exactly 147 packets, as well.

I checked sr(inter=0.05.... do see if the issue is performance related and may be caused by the GIL. However, the issue still occures.

So it's rather something "memory" related. I also receive all the packets over wireshark. So the kernel gets them and everything seems complete.

@polybassa
Copy link
Contributor

I did the following two tests to verify that the issue is not in the dissection of the Packet or in the answer and hashret function:

import threading
import time

import pytest

from scapy.layers.inet import ICMP, IP
from test.testsocket import TestSocket


def test_icmp():
    sender = TestSocket(ICMP)
    receiver = TestSocket(ICMP)
    sender.pair(receiver)

    def answering_machine_thread():
        def answer(pkt):
            resp = ICMP(type="echo-reply", seq=pkt.seq)
            receiver.send(resp)
        receiver.sniff(timeout=2, prn=answer, count=1000)

    sim = threading.Thread(target=answering_machine_thread)
    try:
        sim.start()
        time.sleep(1)
        pkts = sender.sr(ICMP(seq=(1,1000)), timeout=1)
        print(pkts)
    finally:
        sim.join(timeout=5)


def test_ip():
    sender = TestSocket(IP)
    receiver = TestSocket(IP)
    sender.pair(receiver)

    def answering_machine_thread():
        def answer(pkt):
            resp = IP(dst=pkt.src, src=pkt.dst)/ICMP(type="echo-reply", seq=pkt.seq)
            receiver.send(resp)
        receiver.sniff(timeout=2, prn=answer, count=1000)

    sim = threading.Thread(target=answering_machine_thread)
    try:
        sim.start()
        time.sleep(1)
        pkts = sender.sr(IP(dst='111.111.0.1')/ICMP(seq=(1,1000)), timeout=1)
        print(pkts)
    finally:
        sim.join(timeout=5)

Both test receive 1000 pkts.

@polybassa
Copy link
Contributor

(I assume) This should also demonstrate that the sndrcv is not the problem.

@polybassa
Copy link
Contributor

If you run sr with threaded=True, the issue isn't present.

sr(IP(dst='192.168.178.1')/ICMP(seq=(1,1000)), timeout=1, threaded=True)

@GD1200
Copy link
Author

GD1200 commented Sep 17, 2024

If you run sr with threaded=True, the issue isn't present.

sr(IP(dst='192.168.178.1')/ICMP(seq=(1,1000)), timeout=1, threaded=True)

@polybassa, I tried it before, and the result was indeed better. However, there were still a lot (>50%) of unseen answers on a machine with 4 physical cores / 8 threads:

>>> conf.version
'2.6.0rc2.dev2'

>>> sr(IP(dst='172.17.0.1')/ICMP(seq=(1,1000)), timeout=5, threaded=True)
Begin emission:
*************************************************************************************************************************************************************************************************************************************************************************************************************Finished sending 1000 packets.
***************************************************************************************************************************************************
Received 448 packets, got 448 answers, remaining 552 packets
(<Results: TCP:0 UDP:0 ICMP:448 Other:0>, <Unanswered: TCP:0 UDP:0 ICMP:552 Other:0>)


# cat /proc/cpuinfo | grep CPU
model name : Intel(R) Core(TM) i7-10510U CPU @ 1.80GHz
model name : Intel(R) Core(TM) i7-10510U CPU @ 1.80GHz
model name : Intel(R) Core(TM) i7-10510U CPU @ 1.80GHz
model name : Intel(R) Core(TM) i7-10510U CPU @ 1.80GHz
model name : Intel(R) Core(TM) i7-10510U CPU @ 1.80GHz
model name : Intel(R) Core(TM) i7-10510U CPU @ 1.80GHz
model name : Intel(R) Core(TM) i7-10510U CPU @ 1.80GHz
model name : Intel(R) Core(TM) i7-10510U CPU @ 1.80GHz

@GD1200
Copy link
Author

GD1200 commented Sep 17, 2024

I also noticed that with disabled multithreading, I can normally get ~100 more packets in the threaded sr() mode:

# cat /sys/devices/system/cpu/smt/active 
1


>>> conf.version
'2.5.0'

>>> sr(IP(dst='172.17.0.1')/ICMP(seq=(1,1000)), timeout=1, threaded=True)
Begin emission:
***************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************Finished sending 1000 packets.

Received 699 packets, got 699 answers, remaining 301 packets
(<Results: TCP:0 UDP:0 ICMP:699 Other:0>, <Unanswered: TCP:0 UDP:0 ICMP:301 Other:0>)



# echo off > /sys/devices/system/cpu/smt/control
# cat /sys/devices/system/cpu/smt/active 
0


>>> sr(IP(dst='172.17.0.1')/ICMP(seq=(1,1000)), timeout=1, threaded=True)
Begin emission:
*******************************************************************************.***************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************Finished sending 1000 packets.

Received 803 packets, got 802 answers, remaining 198 packets
(<Results: TCP:0 UDP:0 ICMP:802 Other:0>, <Unanswered: TCP:0 UDP:0 ICMP:198 Other:0>)

@polybassa
Copy link
Contributor

Ok, thanks. I was only testing against my router on a physical network. So the "simulated" network might send faster and therefore still cause the packet loss.

But at least, we know that the issue is related to python threading.

Could you do a quick test with bandwidth limitation? I wonder, at which point you would receive 100% if you step by step increase the bandwidth limitation on your virtual network.

@gpotter2
Copy link
Member

gpotter2 commented Sep 17, 2024

Clearly the issue here is with Scapy. I can personally easily reproduce using the script provided by OP.

@GD1200
Copy link
Author

GD1200 commented Sep 17, 2024

Could you do a quick test with bandwidth limitation? I wonder, at which point you would receive 100% if you step by step increase the bandwidth limitation on your virtual network.

After I had shaped my transmission, I noticed changes. Namely, when I shape my TX to 128Kbps, I see all 1k answers registered in threaded mode:

tc qdisc add dev eth0 root handle 1: htb default 1
tc class add dev eth0 parent 1: classid 1:1 htb rate 128kbit

# tc qdisc show dev eth0
qdisc htb 1: root refcnt 9 r2q 10 default 0x1 direct_packets_stat 0 direct_qlen 1000

# tc class show dev eth0
class htb 1:1 root prio 0 rate 128Kbit ceil 128Kbit burst 1600b cburst 1600b 


>>> sr(IP(dst='172.17.0.1')/ICMP(seq=(1,1000)), timeout=1, threaded=True)
Begin emission:
*************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************Finished sending 1000 packets.
***************************************************************************************************************************************************
Received 1000 packets, got 1000 answers, remaining 0 packets
(<Results: TCP:0 UDP:0 ICMP:1000 Other:0>, <Unanswered: TCP:0 UDP:0 ICMP:0 Other:0>)

I also noticed improvements in the default mode mode:

>>> sr(IP(dst='172.17.0.1')/ICMP(seq=(1,1000)), timeout=1)
Begin emission:
Finished sending 1000 packets.
***************************************************************************************************************************************************************************************************************************************************************************************
Received 279 packets, got 279 answers, remaining 721 packets
(<Results: TCP:0 UDP:0 ICMP:279 Other:0>, <Unanswered: TCP:0 UDP:0 ICMP:721 Other:0>)

If I increase the HTB shaper to 256Kbps, I start seeing issues:

# tc class change dev eth0 parent 1: classid 1:1 htb rate 256kbit
# tc class show dev eth0
class htb 1:1 root prio 0 rate 256Kbit ceil 256Kbit burst 1600b cburst 1600b 


>>> sr(IP(dst='172.17.0.1')/ICMP(seq=(1,1000)), timeout=1, threaded=True)
Begin emission:
************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************Finished sending 1000 packets.
*****************************************************************************************************************************************************************************************************************************************************************************************************
Received 833 packets, got 833 answers, remaining 167 packets
(<Results: TCP:0 UDP:0 ICMP:833 Other:0>, <Unanswered: TCP:0 UDP:0 ICMP:167 Other:0>)

@gpotter2
Copy link
Member

gpotter2 commented Sep 24, 2024

fixed by #4538

Thanks again for the report !

@GD1200
Copy link
Author

GD1200 commented Sep 24, 2024

Great job, @polybassa and @gpotter2! Thank you so much for fixing this so swiftly!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug major Major changes
Projects
None yet
Development

No branches or pull requests

3 participants