Delay sending packets after a wireless roam

Delay sending packets after a wireless roam

[Michael Johnson]

Hi all,

I'm having an odd issue with wireless roaming whereby any time I roam
from one access point to another I start receiving packets almost
instantly but experience a delay of roughly 1 second before I can send
packets out. I think I've narrowed it down to somewhere kernel related
but I'm struggling to know where to look next.

Firstly, I started seeing this delay after upgrading from Ubuntu 16.04
(so 4.15 kernel) to 20.04 (tested with 5.4, 5.8 and 5.11) but I also
tested this on Kali 2021.2 (5.10).
I see the delay with intel (iwlwifi), qualcomm (ath10k), and realtek cards.
I've also used both iwd and wpa_supplicant, with and without
systemd-networkd and NetworkManager.
I've been using ICMP for testing but I've also tried a python script
for sending udp packets with the same result.

Here is the output of the simplest test that still shows the issue
(ping + tcpdump + iwd + 5.11.0-27-generic):
https://pastebin.com/92TKKktb

My naive tl;dr of that data is:

30.322638 - we start to roam which falls between icmp_seq=121 and icmp_seq=122.
30.415411 - roam is complete
30.424277 - iwd is sending and receiving neighbor reports over the link
31.358491 - an ARP request is sent out  (should the ARP cache be
cleared on a roam?)
31.367930 - ARP response
31.368009 - packets start being sent again as soon as we get the ARP response

Can anyone help me understand what might be happening between the
interface going "up" at 30.415411 and the ARP request at 31.358491
please?
Also, does anyone else see something in their environment?

Kind Regards,
Michael

Re: Delay sending packets after a wireless roam

[Ben Greear]

On 8/27/21 3:23 AM, Michael Johnson wrote:
> Hi all,
> 
> I'm having an odd issue with wireless roaming whereby any time I roam
> from one access point to another I start receiving packets almost
> instantly but experience a delay of roughly 1 second before I can send
> packets out. I think I've narrowed it down to somewhere kernel related
> but I'm struggling to know where to look next.
> 
> Firstly, I started seeing this delay after upgrading from Ubuntu 16.04
> (so 4.15 kernel) to 20.04 (tested with 5.4, 5.8 and 5.11) but I also
> tested this on Kali 2021.2 (5.10).
> I see the delay with intel (iwlwifi), qualcomm (ath10k), and realtek cards.
> I've also used both iwd and wpa_supplicant, with and without
> systemd-networkd and NetworkManager.
> I've been using ICMP for testing but I've also tried a python script
> for sending udp packets with the same result.
> 
> Here is the output of the simplest test that still shows the issue
> (ping + tcpdump + iwd + 5.11.0-27-generic):
> https://pastebin.com/92TKKktb
> 
> My naive tl;dr of that data is:
> 
> 30.322638 - we start to roam which falls between icmp_seq=121 and icmp_seq=122.
> 30.415411 - roam is complete
> 30.424277 - iwd is sending and receiving neighbor reports over the link
> 31.358491 - an ARP request is sent out  (should the ARP cache be
> cleared on a roam?)
> 31.367930 - ARP response
> 31.368009 - packets start being sent again as soon as we get the ARP response
> 
> Can anyone help me understand what might be happening between the
> interface going "up" at 30.415411 and the ARP request at 31.358491
> please?
> Also, does anyone else see something in their environment?

I think ARP cache should be cleared on roam...I'm not sure how best to do that
though.  wid/supplicant could make the call to clear as soon as roam happens?

Thanks,
Ben

-- 
Ben Greear <greearb@candelatech.com>
Candela Technologies Inc  http://www.candelatech.com

Re: Delay sending packets after a wireless roam

[Michael Johnson]

Hi all,

On Mon, 30 Aug 2021 at 16:37, Michael Johnson <mjohnson459@gmail.com> wrote:
> I started seeing this delay after upgrading from Ubuntu 16.04 to 20.04
> but because so much of the wireless stack changed between those
> releases I'm not sure if it's possible to bisect the change?

Since my last email I have managed to test different kernel versions
to narrow it down to something introduced v4.20-rc1. The issue doesn't
exist in v4.19.
I also compiled and tested the mainline and can confirm that the issue
still exists as of 5.14-rc7.

Does anyone have any suspicions about what commits might cause this issue?

I'm currently trying to bisect the remaining commits but my laptop has
a new intel chip that wasn't supported in old kernel versions and I
can't seem to backport the iwlwifi driver with a compiled kernel (I
could use the backport-iwlwifi repo when installing old debian
packages).

Finally, one other thing I've noticed after more testing is the send
gap is almost exactly one second from the last packet sent before a
roam to the first packet received after. This hints to me it might be
scheduling or timeout related?

Kind Regards,
Michael

Delay sending packets after a wireless roam

[Michael Johnson]

Hi all,

I posted this on linux-wireless last week but didn't receive much
response, I hope it is ok to repeat it here.

I'm having an odd issue with wireless roaming whereby any time I roam
from one access point to another (same SSID) I start receiving packets
instantly after the roam is successful but experience a delay of
roughly 1 second before I can send packets out. I have seen this with
multiple configurations but haven't been able to test with the
mainline kernel yet (working on it now). Listening to the netlink
traffic I can see the roam is successful with the interface going down
and then back up but nothing seems to be logged or sent that hints at
what the delay might be.

I started seeing this delay after upgrading from Ubuntu 16.04 to 20.04
but because so much of the wireless stack changed between those
releases I'm not sure if it's possible to bisect the change?

Configurations I've tested that show this behaviour:
  Distro(kernel) version - 20.04 (5.4, 5.8 and 5.11), Kali 2021.2 (5.10)
  Hardware(driver): intel (iwlwifi), qualcomm (ath10k), realtek.
  Supplicant: iwd and wpa_supplicant
  Manager: iwd, systemd-networkd, NetworkManager
  Data: ping, iperf3 (tcp and udp), custom python udp script
  APs:  Meraki MR46, tp-link decos

Here is the output of the simplest test that still shows the issue
(ping + tcpdump + iwd + 5.11.0-27-generic):
https://pastebin.com/92TKKktb

My naive tl;dr of that data is:
  30.322638 - we start to roam which falls between icmp_seq=121 and
icmp_seq=122.
  30.415411 - roam is complete
  30.424277 - iwd is sending and receiving neighbor reports over the link
  31.358491 - an ARP request is sent out (why is the ARP cache cleared?)
  31.367930 - ARP response
  31.368009 - packets start being sent again as soon as we get the ARP response

Can anyone help me understand what might be happening between the
interface going "up" at 30.415411 and the ARP request at 31.358491
please? I don't think the ARP is the problem given I can clear the arp
cache without any delay but I hope it hints at what the underlying
issue might be.
I'm also curious if anyone else sees the same delay in their environment?

I'm not that familiar with networking in Linux so I apologise if any
of my description/question didn't make sense.

Kind Regards,
Michael