* NetworkManager connection gets stuck in pending state when bringing up AP mode connection with IWD backend
@ 2024-05-06 19:11 James Hilliard
2024-05-06 20:15 ` James Prestwood
0 siblings, 1 reply; 14+ messages in thread
From: James Hilliard @ 2024-05-06 19:11 UTC (permalink / raw)
To: iwd
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
^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: NetworkManager connection gets stuck in pending state when bringing up AP mode connection with IWD backend
2024-05-06 19:11 NetworkManager connection gets stuck in pending state when bringing up AP mode connection with IWD backend James Hilliard
@ 2024-05-06 20:15 ` James Prestwood
2024-05-06 20:34 ` James Hilliard
0 siblings, 1 reply; 14+ messages in thread
From: James Prestwood @ 2024-05-06 20:15 UTC (permalink / raw)
To: James Hilliard, iwd
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
^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: NetworkManager connection gets stuck in pending state when bringing up AP mode connection with IWD backend
2024-05-06 20:15 ` James Prestwood
@ 2024-05-06 20:34 ` James Hilliard
2024-05-06 20:48 ` James Prestwood
0 siblings, 1 reply; 14+ messages in thread
From: James Hilliard @ 2024-05-06 20:34 UTC (permalink / raw)
To: James Prestwood; +Cc: iwd
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?
>
> Thanks,
>
> James
>
^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: NetworkManager connection gets stuck in pending state when bringing up AP mode connection with IWD backend
2024-05-06 20:34 ` James Hilliard
@ 2024-05-06 20:48 ` James Prestwood
2024-05-06 22:40 ` James Hilliard
0 siblings, 1 reply; 14+ messages in thread
From: James Prestwood @ 2024-05-06 20:48 UTC (permalink / raw)
To: James Hilliard; +Cc: iwd
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?
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?
Thanks,
James
>
>> Thanks,
>>
>> James
>>
^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: NetworkManager connection gets stuck in pending state when bringing up AP mode connection with IWD backend
2024-05-06 20:48 ` James Prestwood
@ 2024-05-06 22:40 ` James Hilliard
2024-05-07 11:41 ` James Prestwood
0 siblings, 1 reply; 14+ messages in thread
From: James Hilliard @ 2024-05-06 22:40 UTC (permalink / raw)
To: James Prestwood; +Cc: iwd
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?
>
> Thanks,
>
> James
>
> >
> >> Thanks,
> >>
> >> James
> >>
^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: NetworkManager connection gets stuck in pending state when bringing up AP mode connection with IWD backend
2024-05-06 22:40 ` James Hilliard
@ 2024-05-07 11:41 ` James Prestwood
2024-05-07 17:15 ` James Hilliard
0 siblings, 1 reply; 14+ messages in thread
From: James Prestwood @ 2024-05-07 11:41 UTC (permalink / raw)
To: James Hilliard; +Cc: iwd
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
>>>>
^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: NetworkManager connection gets stuck in pending state when bringing up AP mode connection with IWD backend
2024-05-07 11:41 ` James Prestwood
@ 2024-05-07 17:15 ` James Hilliard
2024-05-07 17:36 ` James Prestwood
0 siblings, 1 reply; 14+ messages in thread
From: James Hilliard @ 2024-05-07 17:15 UTC (permalink / raw)
To: James Prestwood; +Cc: iwd
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).
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.
> >
> >> Thanks,
> >>
> >> James
> >>
> >>>> Thanks,
> >>>>
> >>>> James
> >>>>
^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: NetworkManager connection gets stuck in pending state when bringing up AP mode connection with IWD backend
2024-05-07 17:15 ` James Hilliard
@ 2024-05-07 17:36 ` James Prestwood
2024-05-07 17:47 ` James Hilliard
0 siblings, 1 reply; 14+ messages in thread
From: James Prestwood @ 2024-05-07 17:36 UTC (permalink / raw)
To: James Hilliard; +Cc: iwd
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...
>
>>>> Thanks,
>>>>
>>>> James
>>>>
>>>>>> Thanks,
>>>>>>
>>>>>> James
>>>>>>
^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: NetworkManager connection gets stuck in pending state when bringing up AP mode connection with IWD backend
2024-05-07 17:36 ` James Prestwood
@ 2024-05-07 17:47 ` James Hilliard
2024-05-07 17:50 ` James Prestwood
0 siblings, 1 reply; 14+ messages in thread
From: James Hilliard @ 2024-05-07 17:47 UTC (permalink / raw)
To: James Prestwood; +Cc: iwd
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?
> >
> >>>> Thanks,
> >>>>
> >>>> James
> >>>>
> >>>>>> Thanks,
> >>>>>>
> >>>>>> James
> >>>>>>
^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: NetworkManager connection gets stuck in pending state when bringing up AP mode connection with IWD backend
2024-05-07 17:47 ` James Hilliard
@ 2024-05-07 17:50 ` James Prestwood
2024-05-07 21:26 ` James Hilliard
0 siblings, 1 reply; 14+ messages in thread
From: James Prestwood @ 2024-05-07 17:50 UTC (permalink / raw)
To: James Hilliard; +Cc: iwd
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
>>>>>>>>
^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: NetworkManager connection gets stuck in pending state when bringing up AP mode connection with IWD backend
2024-05-07 17:50 ` James Prestwood
@ 2024-05-07 21:26 ` James Hilliard
2024-05-07 21:40 ` Denis Kenzior
0 siblings, 1 reply; 14+ messages in thread
From: James Hilliard @ 2024-05-07 21:26 UTC (permalink / raw)
To: James Prestwood; +Cc: iwd
On Tue, May 7, 2024 at 11:50 AM James Prestwood <prestwoj@gmail.com> wrote:
>
>
> 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.
Looking into this that doesn't appear to be entirely accurate, that method
seems to be working fine but is not the only API NM uses to interface with
IWD.
It looks like NM is also using this for interface configuration:
https://git.kernel.org/pub/scm/network/wireless/iwd.git/tree/doc/agent-api.txt
During iwd startup NM registers an agent like this:
method call time=1715116624.786278 sender=:1.6 -> destination=:1.55
serial=1587 path=/net/connman/iwd;
interface=net.connman.iwd.AgentManager;
member=RegisterNetworkConfigurationAgent
object path "/org/freedesktop/NetworkManager/iwd/agent"
The documentation indicates:
If no network configuration agent is
present, IWD immediately writes (commits) those
values to the corresponding interface, the routing
table and communicates them to the resolver. If such
agent is registered, IWD requests the agent to do
this last step.
From what I can tell the pending state issue is due to IWD failing to fire
a request to the NetworkConfigurationAgent registered by NM at all as
I'm not seeing any NetworkConfigurationAgent requests when bringing
up the AP interface when monitoring dbus using "dbus-monitor --system".
So I think this may be an IWD bug after all.
>
> >
> >>>>>> Thanks,
> >>>>>>
> >>>>>> James
> >>>>>>
> >>>>>>>> Thanks,
> >>>>>>>>
> >>>>>>>> James
> >>>>>>>>
^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: NetworkManager connection gets stuck in pending state when bringing up AP mode connection with IWD backend
2024-05-07 21:26 ` James Hilliard
@ 2024-05-07 21:40 ` Denis Kenzior
2024-05-07 22:12 ` James Hilliard
0 siblings, 1 reply; 14+ messages in thread
From: Denis Kenzior @ 2024-05-07 21:40 UTC (permalink / raw)
To: James Hilliard, James Prestwood; +Cc: iwd
Hi James,
>>
>> 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.
>
> Looking into this that doesn't appear to be entirely accurate, that method
> seems to be working fine but is not the only API NM uses to interface with
> IWD.
>
> It looks like NM is also using this for interface configuration:
> https://git.kernel.org/pub/scm/network/wireless/iwd.git/tree/doc/agent-api.txt
That is only relevant for Station interfaces (i.e. client mode) if you're
running iwd with EnableNetworkConfiguration=true. The Access Point mode is not
setup to report network configuration details via this infrastructure.
Regards,
-Denis
^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: NetworkManager connection gets stuck in pending state when bringing up AP mode connection with IWD backend
2024-05-07 21:40 ` Denis Kenzior
@ 2024-05-07 22:12 ` James Hilliard
2024-05-07 22:31 ` Denis Kenzior
0 siblings, 1 reply; 14+ messages in thread
From: James Hilliard @ 2024-05-07 22:12 UTC (permalink / raw)
To: Denis Kenzior; +Cc: James Prestwood, iwd
On Tue, May 7, 2024 at 3:40 PM Denis Kenzior <denkenz@gmail.com> wrote:
>
> Hi James,
>
> >>
> >> 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.
> >
> > Looking into this that doesn't appear to be entirely accurate, that method
> > seems to be working fine but is not the only API NM uses to interface with
> > IWD.
> >
> > It looks like NM is also using this for interface configuration:
> > https://git.kernel.org/pub/scm/network/wireless/iwd.git/tree/doc/agent-api.txt
>
> That is only relevant for Station interfaces (i.e. client mode) if you're
> running iwd with EnableNetworkConfiguration=true. The Access Point mode is not
> setup to report network configuration details via this infrastructure.
The docs indicate that RegisterNetworkConfigurationAgent is relevant for:
station-mode, AP-mode or P2P connection
If AP mode doesn't support this interface then how should the network
configuration details be reported to NM when running in AP mode?
>
> Regards,
> -Denis
^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: NetworkManager connection gets stuck in pending state when bringing up AP mode connection with IWD backend
2024-05-07 22:12 ` James Hilliard
@ 2024-05-07 22:31 ` Denis Kenzior
0 siblings, 0 replies; 14+ messages in thread
From: Denis Kenzior @ 2024-05-07 22:31 UTC (permalink / raw)
To: James Hilliard; +Cc: James Prestwood, iwd, Andrew Zaborowski
Hi James,
On 5/7/24 5:12 PM, James Hilliard wrote:
> On Tue, May 7, 2024 at 3:40 PM Denis Kenzior <denkenz@gmail.com> wrote:
>>
>> Hi James,
>>
>>>>
>>>> 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.
>>>
>>> Looking into this that doesn't appear to be entirely accurate, that method
>>> seems to be working fine but is not the only API NM uses to interface with
>>> IWD.
>>>
>>> It looks like NM is also using this for interface configuration:
>>> https://git.kernel.org/pub/scm/network/wireless/iwd.git/tree/doc/agent-api.txt
>>
>> That is only relevant for Station interfaces (i.e. client mode) if you're
>> running iwd with EnableNetworkConfiguration=true. The Access Point mode is not
>> setup to report network configuration details via this infrastructure.
>
> The docs indicate that RegisterNetworkConfigurationAgent is relevant for:
> station-mode, AP-mode or P2P connection
Indeed. But note that NetworkConfigurationAgent API is marked experimental and
there's no infrastructure that would enable AP to invoke this agent at the
moment. It is only integrated with l_netconfig which is used for client side only.
It may be the intent was to add this functionality eventually, but it isn't
there now. I'm surprised NM tries to use it for AP mode actually. Maybe Andrew
(who wrote much of the code on both iwd and NM sides) would know.
>
> If AP mode doesn't support this interface then how should the network
> configuration details be reported to NM when running in AP mode?
Well, I see two options:
- If NM expects IP details from iwd even in AP mode, then teach iwd to do this
- Make NM only use NetworkConfigurationAgent in station mode
Regards,
-Denis
^ permalink raw reply [flat|nested] 14+ messages in thread
end of thread, other threads:[~2024-05-07 22:31 UTC | newest]
Thread overview: 14+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2024-05-06 19:11 NetworkManager connection gets stuck in pending state when bringing up AP mode connection with IWD backend James Hilliard
2024-05-06 20:15 ` James Prestwood
2024-05-06 20:34 ` James Hilliard
2024-05-06 20:48 ` James Prestwood
2024-05-06 22:40 ` James Hilliard
2024-05-07 11:41 ` James Prestwood
2024-05-07 17:15 ` James Hilliard
2024-05-07 17:36 ` James Prestwood
2024-05-07 17:47 ` James Hilliard
2024-05-07 17:50 ` James Prestwood
2024-05-07 21:26 ` James Hilliard
2024-05-07 21:40 ` Denis Kenzior
2024-05-07 22:12 ` James Hilliard
2024-05-07 22:31 ` Denis Kenzior
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).