Failing to resolve after roams

Failing to resolve after roams

[Michael Johnson]

[-- Attachment #1: Type: text/plain, Size: 3161 bytes --]

Hi all,

I'm having a problem with iwd when it comes to roaming. Most of the
time it is working perfectly but rarely I get into this situation
where I can't resolve any hostnames.
I'm using a default server setup on ubuntu which uses systemd-networkd
and systemd-resolved with iwd configured to use
`EnableNetworkConfiguration=true`.

Here are the debug logs of a failure case:
```
Aug 10 09:48:04.120612 p3-631 systemd-networkd[341]: wlan0: Lost carrier
Aug 10 09:48:04.121287 p3-631 kernel: wlan0: send auth to <BSSID> (try 1/3)
Aug 10 09:48:04.123440 p3-631 iwd[413]:
src/netdev.c:netdev_mlme_notify() MLME notification Authenticate(37)
Aug 10 09:48:04.123440 p3-631 iwd[413]: src/netdev.c:netdev_authenticate_event()
Aug 10 09:48:04.125236 p3-631 kernel: wlan0: authenticated
Aug 10 09:48:04.125339 p3-631 kernel: wlan0: associate with <BSSID> (try 1/3)
Aug 10 09:48:04.133316 p3-631 kernel: wlan0: RX ReassocResp from
<BSSID> (capab=0x1511 status=0 aid=8)
Aug 10 09:48:04.134574 p3-631 iwd[413]:
src/netdev.c:netdev_mlme_notify() MLME notification Associate(38)
Aug 10 09:48:04.134574 p3-631 iwd[413]: src/netdev.c:netdev_associate_event()
Aug 10 09:48:04.134574 p3-631 iwd[413]: src/netdev.c:netdev_set_gtk() 5
Aug 10 09:48:04.134574 p3-631 iwd[413]:
src/station.c:station_handshake_event() Setting keys
Aug 10 09:48:04.134574 p3-631 iwd[413]: src/netdev.c:netdev_set_tk() 5
Aug 10 09:48:04.134574 p3-631 iwd[413]:
src/netdev.c:netdev_mlme_notify() MLME notification Connect(46)
Aug 10 09:48:04.134574 p3-631 iwd[413]: src/netdev.c:netdev_connect_event()
Aug 10 09:48:04.135502 p3-631 iwd[413]:
src/station.c:station_fast_transition_cb() 5, result: 0
Aug 10 09:48:04.135502 p3-631 iwd[413]:
src/station.c:station_enter_state() Old State: roaming, new state:
connected
Aug 10 09:48:04.135502 p3-631 iwd[413]:
src/wiphy.c:wiphy_radio_work_done() Work item 315 done
Aug 10 09:48:04.135791 p3-631 iwd[413]:
src/netdev.c:netdev_link_notify() event 16 on ifindex 5
Aug 10 09:48:04.135936 p3-631 iwd[413]:
src/netdev.c:netdev_link_notify() event 16 on ifindex 5
Aug 10 09:48:04.136075 p3-631 iwd[413]:
src/netdev.c:netdev_link_notify() event 16 on ifindex 5
Aug 10 09:48:04.136231 p3-631 iwd[413]:
src/netdev.c:netdev_link_notify() event 16 on ifindex 5
Aug 10 09:48:04.136460 p3-631 iwd[413]: src/wiphy.c:wiphy_reg_notify()
Notification of command Reg Change(36)
Aug 10 09:48:04.136460 p3-631 iwd[413]:
src/wiphy.c:wiphy_update_reg_domain() New reg domain country code for
(global) is US
Aug 10 09:48:04.136741 p3-631 iwd[413]:
src/netdev.c:netdev_mlme_notify() MLME notification Frame TX
Status(60)
Aug 10 09:48:04.137287 p3-631 kernel: wlan0: associated
```
```
$ sudo resolvectl status
...
Link 5 (wlan0)
      Current Scopes: none
```

What I noticed is that when the roam works, there is a
`systemd-networkd[341]: wlan0: Gained carrier` line at the end which
is missing here.
Unfortunately it happens rarely enough that capturing the netlink
traffic is a pain so I can't see if the issue is on the iwd or systemd
side.

Has anyone else seen something like this?

Kind Regards,
Michael

Re: Failing to resolve after roams

[Denis Kenzior]

[-- Attachment #1: Type: text/plain, Size: 720 bytes --]

Hi Michael,

On 8/10/21 5:58 AM, Michael Johnson wrote:
> Hi all,
> 
> I'm having a problem with iwd when it comes to roaming. Most of the
> time it is working perfectly but rarely I get into this situation > where I can't resolve any hostnames.
> I'm using a default server setup on ubuntu which uses systemd-networkd
> and systemd-resolved with iwd configured to use
> `EnableNetworkConfiguration=true`.
> 

Hmm, are you configuring systemd-networkd not to manage wireless interfaces? 
Otherwise iwd and networkd might be fighting each other when it comes to 
managing the network interface.  Generally, one would not set 
'EnableNetworkConfiguration=true' if networkd is being used.

Regards,
-Denis

Re: Failing to resolve after roams

[Michael Johnson]

[-- Attachment #1: Type: text/plain, Size: 1106 bytes --]

Hi Denis,

`systemd-networkd` isn't managing the wireless interface but still
needs to run for wired connections (or at least shouldn't be). I'm not
sure why it still prints connected/disconnect states. How does `iwd`
interact with `systemd-resolved`?

Regards,
Michael

On Thu, 12 Aug 2021 at 15:24, Denis Kenzior <denkenz@gmail.com> wrote:
>
> Hi Michael,
>
> On 8/10/21 5:58 AM, Michael Johnson wrote:
> > Hi all,
> >
> > I'm having a problem with iwd when it comes to roaming. Most of the
> > time it is working perfectly but rarely I get into this situation > where I can't resolve any hostnames.
> > I'm using a default server setup on ubuntu which uses systemd-networkd
> > and systemd-resolved with iwd configured to use
> > `EnableNetworkConfiguration=true`.
> >
>
> Hmm, are you configuring systemd-networkd not to manage wireless interfaces?
> Otherwise iwd and networkd might be fighting each other when it comes to
> managing the network interface.  Generally, one would not set
> 'EnableNetworkConfiguration=true' if networkd is being used.
>
> Regards,
> -Denis

Re: Failing to resolve after roams

[Denis Kenzior]

[-- Attachment #1: Type: text/plain, Size: 1051 bytes --]

Hi Michael,

On 8/12/21 9:30 AM, Michael Johnson wrote:
> Hi Denis,
> 
> `systemd-networkd` isn't managing the wireless interface but still
> needs to run for wired connections (or at least shouldn't be). I'm not

Okay.  Not sure we tested such a setup here...

> sure why it still prints connected/disconnect states. How does `iwd`
> interact with `systemd-resolved`?

iwd uses systemd-resolved dbus API to set up certain information obtained from 
DHCP (DNS, hostname, etc).  See [1].

You can poke around in src/resolve.c in iwd tree for more details.  Right now 
iwd assumes that no IP configuration details change on a roam (which is what 
802.11 says).  There may be networks where this assumption breaks, but we 
haven't seen any yet.  So at the moment, the resolved settings are left 
untouched between roams.

It might help to spy on the resolved dbus interface using dbus-monitor and see 
if we can learn something useful from that.

[1] https://www.freedesktop.org/software/systemd/man/org.freedesktop.resolve1.html

Re: Failing to resolve after roams

[Michael Johnson]

[-- Attachment #1: Type: text/plain, Size: 3371 bytes --]

Hi Denis,

Using dbus-monitor I can see that networkd is sending out messages
during a roam despite being set to "Unmanaged" for this interface.
This appears to trigger a resolved message which I'm guessing is where
the problem is.
I'll see if I can chase this from the systemd side.

```
NAME                         PID PROCESS         USER
CONNECTION    UNIT                        SESSION DESCRIPTION
:1.0                         344 systemd-network systemd-network :1.0
        systemd-networkd.service    -       -
:1.1                         394 systemd-resolve systemd-resolve :1.1
        systemd-resolved.service    -       -
:1.4                       12653 iwd             root            :1.4
        iwd.service                 -       -

---

signal time=1628782447.272527 sender=:1.4 -> destination=(null
destination) serial=49 path=/net/connman/iwd/0/5;
interface=org.freedesktop.DBus.Properties; member=PropertiesChanged
   string "net.connman.iwd.Station"
   array [
      dict entry(
         string "State"
         variant             string "roaming"
      )
   ]
   array [
   ]
signal time=1628782447.340425 sender=:1.0 -> destination=(null
destination) serial=71 path=/org/freedesktop/network1/link/_35;
interface=org.freedesktop.DBus.Properties; member=PropertiesChanged
   string "org.freedesktop.network1.Link"
   array [
      dict entry(
         string "CarrierState"
         variant             string "no-carrier"
      )
      dict entry(
         string "OperationalState"
         variant             string "no-carrier"
      )
   ]
   array [
   ]
signal time=1628782447.341656 sender=:1.1 -> destination=(null
destination) serial=48 path=/org/freedesktop/resolve1;
interface=org.freedesktop.DBus.Properties; member=PropertiesChanged
   string "org.freedesktop.resolve1.Manager"
   array [
      dict entry(
         string "DNS"
         variant             array [
               struct {
                  int32 5
                  int32 2
                  array of bytes [
                     0a 65 40 02
                  ]
               }
            ]
      )
   ]
   array [
   ]
```

On Thu, 12 Aug 2021 at 15:43, Denis Kenzior <denkenz@gmail.com> wrote:
>
> Hi Michael,
>
> On 8/12/21 9:30 AM, Michael Johnson wrote:
> > Hi Denis,
> >
> > `systemd-networkd` isn't managing the wireless interface but still
> > needs to run for wired connections (or at least shouldn't be). I'm not
>
> Okay.  Not sure we tested such a setup here...
>
> > sure why it still prints connected/disconnect states. How does `iwd`
> > interact with `systemd-resolved`?
>
> iwd uses systemd-resolved dbus API to set up certain information obtained from
> DHCP (DNS, hostname, etc).  See [1].
>
> You can poke around in src/resolve.c in iwd tree for more details.  Right now
> iwd assumes that no IP configuration details change on a roam (which is what
> 802.11 says).  There may be networks where this assumption breaks, but we
> haven't seen any yet.  So at the moment, the resolved settings are left
> untouched between roams.
>
> It might help to spy on the resolved dbus interface using dbus-monitor and see
> if we can learn something useful from that.
>
> [1] https://www.freedesktop.org/software/systemd/man/org.freedesktop.resolve1.html

Re: Failing to resolve after roams

[Denis Kenzior]

[-- Attachment #1: Type: text/plain, Size: 1150 bytes --]

Hi Michael,

On 8/12/21 11:57 AM, Michael Johnson wrote:
> Hi Denis,
> 
> Using dbus-monitor I can see that networkd is sending out messages
> during a roam despite being set to "Unmanaged" for this interface.
> This appears to trigger a resolved message which I'm guessing is where
> the problem is.

So carrier disappearing is expected.  Kernel/driver takes away the carrier when 
it disassociates from the current AP.  Carrier should be restored once we 
associate to the new AP and iwd should be setting the device back up after the 
roam.  This happens in netdev_connect_ok(), l_rtnl_set_linkmode_and_operstate() 
invocation.

What is unclear is why the carrier is sometimes not restored according to 
networkd.  Looking at the log in your first post on this topic I see that 
station_fast_transition_cb() is called and station goes from roaming to 
connected state.  So that would imply that netdev_connect_ok is called in the 
'failure' case (since connect_cb would be set to station_fast_transition_cb) and 
we should have restored carrier earlier.

Any chance you have iwmon logs of this happening?

Regards,
-Denis

Re: Failing to resolve after roams

[Michael Johnson]

[-- Attachment #1: Type: text/plain, Size: 1496 bytes --]

Hi Denis,

I don't have iwmon logs but I can try to get some. I'm not sure how
long it will take but I started a rolling capture and will let you
know when I get something.
Thanks for helping with this.

Regards,
Michael

On Thu, 12 Aug 2021 at 18:32, Denis Kenzior <denkenz@gmail.com> wrote:
>
> Hi Michael,
>
> On 8/12/21 11:57 AM, Michael Johnson wrote:
> > Hi Denis,
> >
> > Using dbus-monitor I can see that networkd is sending out messages
> > during a roam despite being set to "Unmanaged" for this interface.
> > This appears to trigger a resolved message which I'm guessing is where
> > the problem is.
>
> So carrier disappearing is expected.  Kernel/driver takes away the carrier when
> it disassociates from the current AP.  Carrier should be restored once we
> associate to the new AP and iwd should be setting the device back up after the
> roam.  This happens in netdev_connect_ok(), l_rtnl_set_linkmode_and_operstate()
> invocation.
>
> What is unclear is why the carrier is sometimes not restored according to
> networkd.  Looking at the log in your first post on this topic I see that
> station_fast_transition_cb() is called and station goes from roaming to
> connected state.  So that would imply that netdev_connect_ok is called in the
> 'failure' case (since connect_cb would be set to station_fast_transition_cb) and
> we should have restored carrier earlier.
>
> Any chance you have iwmon logs of this happening?
>
> Regards,
> -Denis