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

[James Prestwood <prestwoj@gmail.com>]

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.

Thanks,

James