Investigate Delay Time Between TUN Pings

[kb1lqc]

I believe that the observed 1 second or so of delay when using ping with the faradayio-cli module (which uses faradayio) might be coming from faradayio. Investigate, document, and possibly fix what's going on. This is a bug because 1 second ping times is pretty unacceptable.

[kb1lqc]

Using an FTDI USB to serial converter dongle with a physical wire which I'm pretty sure is a UMFT201XB-WE from DigiKey I am going to test the delay in the system. A physical wire is connecting RX/TX so this is quite literally a loopback test in the physical world.

Test Configuration

The serial port has been left setup in the standard 115200 baud rate on my faradayio-cli command. This should send a single bit in about 8.68us (this is just 1/115200). Per wireshark a single ICMP packet is 84 bytes on the wire. This is 672 bits and at 115200 baud this should take 672 * 8.68us = 5.83ms

Single Ping Test

Right off-the-bat I send a single ping and the following packets are shown on wireshark:

This is a pure loopback so ping will never obtain a real ICMP reply echo, only an exact copy of the packet will be sent back. However, I expect this to be fast. As shown above there is a massive 1.014 second delay. This seems completely insane compared to 5ms serial port communications baud rate time.

Now, I would expect maybe it takes a little time to read the ping packet it. While I'm not sure it's completely parallel or completely 2x the time, let's assume it's 2x the time (5.82ms to send, 5.83ms to receive) over the serial port. This still leaves the TUN 988.3ms to operate. What's going on?

[kb1lqc]

Using simple time statements (avoiding the overhead of timeit at the moment) I can see that the following times are needed for operations

• faraday.send(): 0.00020170211791992188 seconds
• faraday.receive(): 0.0005137920379638672 seconds
• Monitor.checkTUN(): 0.5219976902008057 seconds
• Monitor.checkSerial(): 0.0003154277801513672 seconds (variable but this is roughly average)

Well the elephant in the room is Monitor.checkTUN()... What's going on?

[kb1lqc]

All Monitor.checkTUN is doing is reading up to the mtu from the TUN adapter:

    def checkTUN(self):
        """
        Checks the TUN adapter for data and returns any that is found.

        Returns:
            packet: Data read from the TUN adapter
        """
        packet = self._TUN._tun.read(self._TUN._tun.mtu)
        return(packet)

I wonder if this changes drastically with the size of the mtu... let's find out.

Checking checkTUN() Time Again

Interesting, the first check is always slow but subsequent are fast. I send five ICMP pings to the serial port via faradayio-cli

Executing faradayio-cli version 0.0.4
0.3873627185821533
8.296966552734375e-05
9.72747802734375e-05
8.296966552734375e-05
8.344650268554688e-05

[kb1lqc]

Yes, the first of the five packets always takes about a second (this would make sense at 500ms each way):

What's going on? Does this have something to do with creating an instance or something?

[kb1lqc]

I changed my mtu to 68 bytes and this is MUCH faster:

However, now I have some fragmentation or something... What I think is going on is that I'm waiting for the MTU and then timing out. I bet with a 68 bytes mtu and having 84 this overflows the mtu and causing immediate return. Does pytun have a timeout setting? Also, should I just use a smaller mtu?

[hdkmike]

@kb1lqc , can you attach (or send me) your PCAP file of this?

[kb1lqc]

OK come to find out, the speed of the run() function when I send five independent pings at 400ms and then another 5 at 300ms intervals with a mtu size of 200 results in:

1.0100433826446533
1.009638786315918
1.013122320175171
1.009099006652832
0.7906229496002197
0.421112060546875
0.4097559452056885
0.41944026947021484
0.4108285903930664
1.012366771697998
1.012256383895874
1.0102813243865967
1.010915756225586
1.0121045112609863
1.0100648403167725
1.01291823387146
0.8478987216949463
0.3285524845123291
0.31783199310302734
0.3188364505767822
0.31899547576904297
1.0128042697906494
1.0098042488098145
1.0042800903320312
1.0124406814575195
1.0111093521118164

This shows that the timeouts are causing initial delays and if I send data at the wrong moment of each check it could take up to 2 seconds over an RF link...

[kb1lqc]

@montag451 is there a timeout for a TUN read call in your TUN/TAP module?

[kb1lqc]

Oh boy haha @hdkmike I set a 1 second timeout on the TUN with a timeout decorator..

https://github.com/FaradayRF/faradayio/blob/develop/faradayio/faraday.py#L162

I remember this now, pytun waits indefinitely until data is obtained so the run() loop would stall. That's why I added a timeout. I presume if I make this asynchronous or in two threads I won't have to do a timeout at all...

[kb1lqc]

@hdkmike here's a PCAP of several normal pings (I believe 68 bytes, but could be 84 or so on the wire?) with a --mtu of 200 which should fit all packets. I send several at 3 second intervals then stopped for a bit (see the time jump) then send a bunch at 500ms intervals. FaradayRF_3-12-2018.pcapng.tar.gz

[hdkmike]

@kb1lqc , that'll do it! I've run across this before doing basic "socket pumps" (i.e. send data from one socket to another). This is definitely the right track. asyncio is probably the most elegant way to do this. Has @reillyeon weighed in yet?

[hdkmike]

Also, thanks for the PCAP.

[reillyeon]

Asynchronous is always better. 😄

[hdkmike]

:point_up_2: Agreed!

[kb1lqc]

@hdkmike @reillyeon OK looks like I'll be working on https://github.com/FaradayRF/faradayio/issues/65