From: James Hilliard <james.hilliard1@gmail.com>
To: James Prestwood <prestwoj@gmail.com>
Cc: iwd@lists.linux.dev
Subject: Re: NetworkManager connection gets stuck in pending state when bringing up AP mode connection with IWD backend
Date: Tue, 7 May 2024 15:26:45 -0600 [thread overview]
Message-ID: <CADvTj4pYPBbvEDBoTnEZacE-Ah7S7wgCBYkJoonUMfac1o64ag@mail.gmail.com> (raw)
In-Reply-To: <8b2156c0-7b98-4bc8-ab1a-5009389e5e83@gmail.com>
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
> >>>>>>>>
next prev parent reply other threads:[~2024-05-07 21:26 UTC|newest]
Thread overview: 14+ messages / expand[flat|nested] mbox.gz Atom feed top
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 [this message]
2024-05-07 21:40 ` Denis Kenzior
2024-05-07 22:12 ` James Hilliard
2024-05-07 22:31 ` Denis Kenzior
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=CADvTj4pYPBbvEDBoTnEZacE-Ah7S7wgCBYkJoonUMfac1o64ag@mail.gmail.com \
--to=james.hilliard1@gmail.com \
--cc=iwd@lists.linux.dev \
--cc=prestwoj@gmail.com \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
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 read-only IMAP folder(s) and NNTP newsgroup(s).