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

[James Prestwood <prestwoj@gmail.com>]

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?
>
>> Thanks,
>>
>> James
>>
>>>> Thanks,
>>>>
>>>> James
>>>>