Re: NetworkManager connection gets stuck in pending state when bringing up AP mode connection with IWD backend

[James Prestwood <prestwoj@gmail.com>]

On 5/7/24 10:47 AM, James Hilliard wrote:
> On Tue, May 7, 2024 at 11:36 AM James Prestwood <prestwoj@gmail.com> wrote:
>>
>> On 5/7/24 10:15 AM, James Hilliard wrote:
>>> On Tue, May 7, 2024 at 5:41 AM James Prestwood <prestwoj@gmail.com> wrote:
>>>> On 5/6/24 3:40 PM, James Hilliard wrote:
>>>>> On Mon, May 6, 2024 at 2:49 PM James Prestwood <prestwoj@gmail.com> wrote:
>>>>>> Hi,
>>>>>>
>>>>>> On 5/6/24 1:34 PM, James Hilliard wrote:
>>>>>>> On Mon, May 6, 2024 at 2:15 PM James Prestwood <prestwoj@gmail.com> wrote:
>>>>>>>> Hi James,
>>>>>>>>
>>>>>>>> On 5/6/24 12:11 PM, James Hilliard wrote:
>>>>>>>>> It's a bit unclear if this is a NetworkManager bug or an IWD bug but
>>>>>>>>> I'm unable to successfully bring up AP mode connection in
>>>>>>>>> NetworkManager when using the IWD backend.
>>>>>>>>>
>>>>>>>>> It appears that NetworkManager fails to recognize that IWD has brought
>>>>>>>>> up the AP successfully for some reason even though the AP is
>>>>>>>>> active(i.e. devices can connect to the AP). This results in
>>>>>>>>> NetworkManager failing to appropriately configure the routes needed
>>>>>>>>> for the AP.
>>>>>>>>>
>>>>>>>>> Logs from NetworkManager:
>>>>>>>>> <debug> [1709938743.1640] device[e4bcd76bde98e8a1] (wlan0):
>>>>>>>>> Activation: (wifi) Called Start('APSSID').
>>>>>>>>> <debug> [1709938743.1641] device[e4bcd76bde98e8a1] (wlan0):
>>>>>>>>> Activation: (wifi) IWD Device.Mode set successfully
>>>>>>>>> <debug> [1709938743.1644] device[e4bcd76bde98e8a1] (wlan0):
>>>>>>>>> remove_pending_action (1): 'recheck-available'
>>>>>>>>> <trace> [1709938743.2594] platform: (wlan0) emit signal
>>>>>>>>> ip4-address-changed added: 192.168.45.129/28 brd 0.0.0.0 lft forever
>>>>>>>>> pref forever lifetime 1235-0[4294967295,4294967295] dev 5 flags
>>>>>>>>> permanent src kernel
>>>>>>>>> <debug> [1709938743.2595] platform: (wlan0) signal: address 4   added:
>>>>>>>>> 192.168.45.129/28 brd 0.0.0.0 lft forever pref forever lifetime
>>>>>>>>> 1235-0[4294967295,4294967295] dev 5 flags permanent src kernel
>>>>>>>>> <trace> [1709938743.2598] platform: (wlan0) emit signal
>>>>>>>>> ip4-route-changed added: type local table 255 192.168.45.129/32 dev 5
>>>>>>>>> metric 0 mss 0 rt-src rt-kernel scope host pref-src 192.168.45.129
>>>>>>>>> <debug> [1709938743.2599] platform: (wlan0) signal: route   4   added:
>>>>>>>>> type local table 255 192.168.45.129/32 dev 5 metric 0 mss 0 rt-src
>>>>>>>>> rt-kernel scope host pref-src 192.168.45.129
>>>>>>>>> <trace> [1709938743.2602] platform: (wlan0) emit signal
>>>>>>>>> ip4-route-changed added: type unicast 192.168.45.128/28 dev 5 metric 0
>>>>>>>>> mss 0 rt-src rt-kernel rtm_flags linkdown scope link pref-src
>>>>>>>>> 192.168.45.129
>>>>>>>>> <debug> [1709938743.2602] platform: (wlan0) signal: route   4   added:
>>>>>>>>> type unicast 192.168.45.128/28 dev 5 metric 0 mss 0 rt-src rt-kernel
>>>>>>>>> rtm_flags linkdown scope link pref-src 192.168.45.129
>>>>>>>>> <trace> [1709938743.2609] platform: (wlan0) emit signal link-changed
>>>>>>>>> changed: 5: wlan0 <UP,LOWER_UP;broadcast,multicast,up,running,lowerup>
>>>>>>>>> mtu 1500 arp 1 wifi? init addrgenmode none addr BC:25:F0:1D:6A:03
>>>>>>>>> permaddr BC:25:F0:1D:6A:03 brd FF:FF:FF:FF:FF:FF driver rtl8821ae
>>>>>>>>> tx-queue-len 1000 gso-max-size 65536 gso-max-segs 65535 gro-max-size
>>>>>>>>> 65536 rx:443,42144 tx:563,224232
>>>>>>>>> <debug> [1709938743.2610] platform: (wlan0) signal: link changed: 5:
>>>>>>>>> wlan0 <UP,LOWER_UP;broadcast,multicast,up,running,lowerup> mtu 1500
>>>>>>>>> arp 1 wifi? init addrgenmode none addr BC:25:F0:1D:6A:03 permaddr
>>>>>>>>> BC:25:F0:1D:6A:03 brd FF:FF:FF:FF:FF:FF driver rtl8821ae tx-queue-len
>>>>>>>>> 1000 gso-max-size 65536 gso-max-segs 65535 gro-max-size 65536
>>>>>>>>> rx:443,42144 tx:563,224232
>>>>>>>>> <debug> [1709938743.2611] device[e4bcd76bde98e8a1] (wlan0): queued
>>>>>>>>> link change for ifindex 5
>>>>>>>>> <info>  [1709938743.2657] device (wlan0): Activation: (wifi) Stage 2
>>>>>>>>> of 5 (Device Configure) successful.  Started 'APSSID'.
>>>>>>>>> <debug> [1709938743.2658] device[e4bcd76bde98e8a1] (wlan0):
>>>>>>>>> activation-stage: schedule activate_stage3_ip_config
>>>>>>>>> <debug> [1709938743.2659] device[e4bcd76bde98e8a1] (wlan0):
>>>>>>>>> activation-stage: invoke activate_stage3_ip_config
>>>>>>>>> <debug> [1709938743.2660] device[e4bcd76bde98e8a1] (wlan0):
>>>>>>>>> activation-stage: synchronously invoke activate_stage3_ip_config
>>>>>>>>> <debug> [1709938743.2661] device[e4bcd76bde98e8a1] (wlan0): ip4:
>>>>>>>>> required-timeout: disabled
>>>>>>>>> <debug> [1709938743.2661] device[e4bcd76bde98e8a1] (wlan0): ip6:
>>>>>>>>> required-timeout: disabled
>>>>>>>>> <debug> [1709938743.2662] active-connection[c8d123b3d4d3f96d]: set
>>>>>>>>> state-flags layer2-ready (was none)
>>>>>>>>> <info>  [1709938743.2664] device (wlan0): state change: config ->
>>>>>>>>> ip-config (reason 'none', sys-iface-state: 'managed')
>>>>>>>>> <debug> [1709938743.2699] device[e4bcd76bde98e8a1] (wlan0):
>>>>>>>>> add_pending_action (2): 'in-state-change'
>>>>>>>>> <debug> [1709938743.2704] device[e4bcd76bde98e8a1] (wlan0):
>>>>>>>>> remove_pending_action (1): 'in-state-change'
>>>>>>>>> <info>  [1709938743.2709] device (wlan0): IWD AP/AdHoc state is now Started
>>>>>>>>> <trace> [1709938743.2710] device[e4bcd76bde98e8a1] (wlan0): ip4:
>>>>>>>>> check-state: state pending => pending, is_failed=0, is_pending=0,
>>>>>>>>> is_started=0 temp_na=0, may-fail-4=1, may-fail-6=1;;;
>>>>>>>>> <trace> [1709938743.2710] device[e4bcd76bde98e8a1] (wlan0): ip:
>>>>>>>>> check-state: (combined) state pending => pending
>>>>>>>>> <trace> [1709938743.2711] device[e4bcd76bde98e8a1] (wlan0): ip6:
>>>>>>>>> check-state: state pending => pending, is_failed=0, is_pending=0,
>>>>>>>>> is_started=0 temp_na=0, may-fail-4=1, may-fail-6=1;;;
>>>>>>>>> <trace> [1709938743.2711] device[e4bcd76bde98e8a1] (wlan0): ip:
>>>>>>>>> check-state: (combined) state pending => pending
>>>>>>>>>
>>>>>>>>> NetworkManager bug report with some more details:
>>>>>>>>> https://gitlab.freedesktop.org/NetworkManager/NetworkManager/-/issues/1498
>>>>>>>> This does seem like an NM bug if your able to connect to the AP. That
>>>>>>>> means IWD is doing its part. Fwiw I just tried using NM 1.36.6 and IWD
>>>>>>>> 2.16 and was able to connect with my phone, saw it had an IP etc.
>>>>>>> Yeah, it does get an IP for me as well, but routes are not configured so
>>>>>>> no internet for the connecting device. What's unclear is how NM is supposed
>>>>>>> to detect this state change, does it do that over dbus or something?
>>>>>>>
>>>>>>> Does NM also report a pending state for you?
>>>>>> I'm not very familiar with NM to be honest, but is this what your
>>>>>> looking for?
>>>>> Can you see what the NM logs show when bringing up the connection?
>>>>>
>>>>> I think you may need to enable trace logging like this or something:
>>>>> nmcli general logging level TRACE domains ALL
>>>>>
>>>>>> jprestwood@LOCLAP699:~$ nmcli device show wlan0
>>>>>> GENERAL.DEVICE:                       wlan0
>>>>>> GENERAL.TYPE:                           wifi
>>>>>> GENERAL.HWADDR:                    <MAC>
>>>>>> GENERAL.MTU:                           1500
>>>>>> GENERAL.STATE:                         100 (connected)
>>>>>> GENERAL.CONNECTION:             Hotspot
>>>>>> GENERAL.CON-PATH: /org/freedesktop/NetworkManager/ActiveConnection/12
>>>>>> IP4.ADDRESS[1]:                        10.42.0.1/24
>>>>>> IP4.ADDRESS[2]:                        192.168.135.17/28
>>>>>> IP4.GATEWAY:                              --
>>>>>> IP4.ROUTE[1]:                            dst = 10.42.0.0/24, nh =
>>>>>> 0.0.0.0, mt = 600
>>>>>> IP4.ROUTE[2]:                            dst = 169.254.0.0/16, nh =
>>>>>> 0.0.0.0, mt = 1000
>>>>>> IP4.ROUTE[3]:                            dst = 192.168.135.16/28, nh =
>>>>>> 0.0.0.0, mt = 0
>>>>>> IP6.ADDRESS[1]: fe80::ae2e:3bf6:3828:d928/64
>>>>>> IP6.GATEWAY:                             --
>>>>>> IP6.ROUTE[1]:                            dst = fe80::/64, nh = ::, mt = 1024
>>>>>>
>>>>>> My phone has a 192. address so I assume ROUTE[3] is the right route?
>>>>> Hmm, can it reach the internet or devices not on the 192 network?
>>>> I wasn't able to test this yesterday, but with my laptop now on eth I
>>>> see the same behavior. I get not internet connection from the hotspot.
>>>> Still, this does seem like a NM bug because in this context IWD isn't
>>>> doing anything with IPs/routes. As far as wifi is concerned IWD is
>>>> operating correctly. Does this work with wpa_supplicant for you?
>>> Yeah, I suspect it's a NM bug but I'm thinking it could in theory be an IWD
>>> issue if NM is expecting some sort of notification from IWD that IWD isn't
>>> sending correctly(I don't really understand how the applications interface
>>> with each other well enough however to say one way or another with any
>>> reasonable degree of confidence).
>> Yeah perhaps. The only notification IWD provides is after it starts the
>> AP, just via the DBus reply. From what I could see the route did exist
>> when I tested it maybe it just wasn't set up correctly.
>>> I've tested with wpa_supplication which does not have this issue, although
>>> I've seen an unrelated issue with wpa_supplication(encryption doesn't work)
>>> but when creating an unencrypted AP network everything seems to work ok
>>> with wpa_supplicant as the routes do get set up there.
>> Hmm, its probably a NM/IWD interaction issue then. I'd have to take a
>> look at the NM code, but from what I could see it seemed to be acting
>> like IWD was working. Said the hotspot was running and everything...
> Is there any detailed documentation/references on how the DBus API
> interface between NM/IWD is supposed to work?

NM is just using:

https://git.kernel.org/pub/scm/network/wireless/iwd.git/tree/doc/access-point-api.txt

Should only be using the Start(ssid, psk) method. Its really that simple 
so I don't see how it could really get anything wrong as far as being 
notified. But again, I'm not too familiar with NM.

>
>>>>>> Thanks,
>>>>>>
>>>>>> James
>>>>>>
>>>>>>>> Thanks,
>>>>>>>>
>>>>>>>> James
>>>>>>>>