You are not logged in.

#1 2019-04-04 23:54:42

Brocellous
Member
Registered: 2017-11-27
Posts: 134

[Solved] Unable to connect to wireless using iwd 0.16

So I've been using iwd for a while and its generally worked great. iwd version 0.16 was pushed to community a few hours ago and I updated, but I'm not able to connect at all using version 0.16.

iwd was the only package updated. It still is unable to connect after a reboot. I tried removing my /var/lib/iwd/my-wifi.psk and connecting manually with iwctl but no dice. So I downgraded to 0.14 again and it automatically reconnects just fine.

Every connection attempt from iwctl on version 0.16 reports "operation failed" and is accompanied by the following lines in the journal:

v0.16-1

Apr 04 16:13:30 rxps kernel: wlp2s0: authenticate with a4:56:cc:05:d7:8e
Apr 04 16:13:30 rxps kernel: wlp2s0: send auth to a4:56:cc:05:d7:8e (try 1/3)
Apr 04 16:13:30 rxps kernel: wlp2s0: authenticated
Apr 04 16:13:30 rxps kernel: wlp2s0: associate with a4:56:cc:05:d7:8e (try 1/3)
Apr 04 16:13:30 rxps kernel: wlp2s0: RX AssocResp from a4:56:cc:05:d7:8e (capab=0x1511 status=0 aid=9)
Apr 04 16:13:30 rxps kernel: wlp2s0: associated
Apr 04 16:13:30 rxps kernel: wlp2s0: deauthenticating from a4:56:cc:05:d7:8e by local choice (Reason: 1=UNSPECIFIED)

UNSPECIFIED is not partiularly helpful...

for reference on 0.14 I see

v0.14-1

Apr 04 16:15:02 rxps kernel: wlp2s0: authenticate with a4:56:cc:05:d7:8e
Apr 04 16:15:02 rxps kernel: wlp2s0: send auth to a4:56:cc:05:d7:8e (try 1/3)
Apr 04 16:15:02 rxps kernel: wlp2s0: authenticated
Apr 04 16:15:02 rxps kernel: wlp2s0: associate with a4:56:cc:05:d7:8e (try 1/3)
Apr 04 16:15:02 rxps kernel: wlp2s0: RX AssocResp from a4:56:cc:05:d7:8e (capab=0x1511 status=0 aid=8)
Apr 04 16:15:02 rxps kernel: wlp2s0: associated
Apr 04 16:15:02 rxps systemd-networkd[317]: wlp2s0: Gained carrier
...

And systemd-networkd does its thing.

I tried modifying 'ExecStart=/usr/lib/iwd/iwd' in the iwd.service file to include '-d' for debugging and connecting again, but I don't see anything interesting

v0.16-1 debug

Apr 04 16:33:03 rxps iwd[4633]: src/station.c:station_autoconnect_next() Considering autoconnecting to BSS 'a4:56:cc:05:d7:8e' with SSID: house3-5, freq: 5180, rank: 9126, strength: -5400
Apr 04 16:33:03 rxps iwd[4633]: src/station.c:station_enter_state() Old State: autoconnect_quick, new state: connecting
Apr 04 16:33:03 rxps iwd[4633]: src/scan.c:scan_periodic_stop() Stopping periodic scan for ifindex: 2
Apr 04 16:33:03 rxps iwd[4633]: src/netdev.c:netdev_mlme_notify() MLME notification 19
Apr 04 16:33:03 rxps iwd[4633]: src/station.c:station_netdev_event() Associating
Apr 04 16:33:03 rxps kernel: wlp2s0: send auth to a4:56:cc:05:d7:8e (try 1/3)
Apr 04 16:33:03 rxps iwd[4633]: src/netdev.c:netdev_mlme_notify() MLME notification 37
Apr 04 16:33:03 rxps iwd[4633]: src/netdev.c:netdev_authenticate_event()
Apr 04 16:33:03 rxps kernel: wlp2s0: authenticated
Apr 04 16:33:03 rxps kernel: wlp2s0: associate with a4:56:cc:05:d7:8e (try 1/3)
Apr 04 16:33:04 rxps kernel: wlp2s0: RX AssocResp from a4:56:cc:05:d7:8e (capab=0x1511 status=0 aid=8)
Apr 04 16:33:04 rxps iwd[4633]: src/netdev.c:netdev_mlme_notify() MLME notification 38
Apr 04 16:33:04 rxps iwd[4633]: src/netdev.c:netdev_associate_event()
Apr 04 16:33:04 rxps iwd[4633]: src/netdev.c:netdev_mlme_notify() MLME notification 46
Apr 04 16:33:04 rxps iwd[4633]: src/netdev.c:netdev_connect_event()
Apr 04 16:33:04 rxps kernel: wlp2s0: associated
Apr 04 16:33:04 rxps kernel: wlp2s0: deauthenticating from a4:56:cc:05:d7:8e by local choice (Reason: 1=UNSPECIFIED)
Apr 04 16:33:04 rxps iwd[4633]: src/netdev.c:netdev_mlme_notify() MLME notification 64
Apr 04 16:33:04 rxps iwd[4633]: src/netdev.c:netdev_mlme_notify() MLME notification 20
Apr 04 16:33:04 rxps iwd[4633]: src/netdev.c:netdev_mlme_notify() MLME notification 39
Apr 04 16:33:04 rxps iwd[4633]: src/netdev.c:netdev_deauthenticate_event()
Apr 04 16:33:04 rxps iwd[4633]: src/netdev.c:netdev_mlme_notify() MLME notification 48
Apr 04 16:33:04 rxps iwd[4633]: src/netdev.c:netdev_disconnect_event()
Apr 04 16:33:04 rxps iwd[4633]: src/station.c:station_connect_cb() 2, result: 2
Apr 04 16:33:04 rxps iwd[4633]: src/station.c:station_disassociated() 2
Apr 04 16:33:04 rxps iwd[4633]: src/station.c:station_enter_state() Old State: connecting, new state: disconnected

iwd doesn't come with a man page so I'm not sure where to go from here. Any ideas?

Last edited by Brocellous (2019-04-09 23:00:05)

Offline

#2 2019-04-05 03:41:34

amish
Member
Registered: 2014-05-10
Posts: 470

Re: [Solved] Unable to connect to wireless using iwd 0.16

Yes I am seeing exact same issue.

With iwd 0.16, it authenticates and then de-authenticates with reason as local choice!

Anyone knows what is local choice.

My log and @Brocellous logs are more or less same except that codes (capab, aid) are different.

Apr 05 08:43:25 amish kernel: wlan0: authenticate with 80:37:73:ff:cc:11
Apr 05 08:43:25 amish kernel: wlan0: send auth to 80:37:73:ff:cc:11 (try 1/3)
Apr 05 08:43:25 amish kernel: wlan0: authenticated
Apr 05 08:43:25 amish kernel: wlan0: associate with 80:37:73:ff:cc:11 (try 1/3)
Apr 05 08:43:25 amish kernel: wlan0: RX AssocResp from 80:37:73:ff:cc:11 (capab=0x411 status=0 aid=1)
Apr 05 08:43:25 amish kernel: wlan0: associated
Apr 05 08:43:25 amish kernel: wlan0: deauthenticating from 80:37:73:ff:cc:11 by local choice (Reason: 1=UNSPECIFIED)

Downgrade to 0.14 works fine.

Update:
Looking at commit logs - I tried disabling most options in /etc/iwd/main.conf (https://git.kernel.org/pub/scm/network/ … /main.conf) that were introduced after 0.14. But it didnt work.

There were many changes to iwd.service file. So I even used iwd.service from 0.14 in 0.16 - but still authenticates and de-authenticates.

Overall - whatever I tried, failed. So looks like some upstream code change is breaking my connection.

Last edited by amish (2019-04-05 08:13:10)

Offline

#3 2019-04-05 05:00:48

Brocellous
Member
Registered: 2017-11-27
Posts: 134

Re: [Solved] Unable to connect to wireless using iwd 0.16

Well glad to know I'm not alone. For completeness sake I'll mention I also thought to try the 0.14 service file with the 0.16 daemon and saw no change. I wonder what could be causing this.

Offline

#4 2019-04-05 22:55:37

Brocellous
Member
Registered: 2017-11-27
Posts: 134

Re: [Solved] Unable to connect to wireless using iwd 0.16

EDIT: I'm a moron. You can disregard this post, and I still don't know whats wrong.

OK so I've made some more attempts to fix this and I've got good and bad news.

The good news is its fixed, the bad news is I don't know why.

I'm not the most experienced C programmer, but I thought I'd give this a shot anyway. I couldn't think of how to attach gdb to iwd before it tries to connect so I just peppered the file I thought was responsible with warning level logging messages. After I built and installed, I had version 0.16 working like a charm with no changes to anything but logging! I thought for sure its just from building from source so I tried again with the original source files. Same error. So I add the logging messages back in one at a time and in fact there is one log message that appears to fix iwd for me! Worst of all, its never even logged!

Here is my 'patch' and procedure in detail:

abort.patch (only 1 line added !!)

--- /home/ronan/work/extra/tar-iwd/src/netdev.c	2019-04-03 10:59:41.000000000 -0700
+++ src/iwd-0.16/src/netdev.c	2019-04-05 15:32:28.144151979 -0700
@@ -2379,6 +2379,7 @@
 	l_debug("");
 
 	if (netdev->aborting)
+		l_warn("aborting");
 		return;
 
 	if (!l_genl_attr_init(&attr, msg)) {

building the patched iwd

$ asp export iwd
$ cd iwd
$ makepkg --verifysource
$ patch src/iwd-0.16/src/netdev.c abort.patch
$ makepkg -ei

And here is 0.16 working just fine after the 'patch'

$ systemctl status iwd.service
● iwd.service - Wireless service
   Loaded: loaded (/usr/lib/systemd/system/iwd.service; enabled; vendor preset: disabled)
   Active: active (running) since Fri 2019-04-05 15:18:12 PDT; 23min ago
 Main PID: 25839 (iwd)
    Tasks: 1 (limit: 4915)
   Memory: 924.0K
   CGroup: /system.slice/iwd.service
           └─25839 /usr/lib/iwd/iwd

Apr 05 15:18:12 rxps systemd[1]: Starting Wireless service...
Apr 05 15:18:12 rxps iwd[25839]: Wireless daemon version 0.16
Apr 05 15:18:12 rxps iwd[25839]: Skipping optional configuration file /etc/iwd/main.conf
Apr 05 15:18:12 rxps systemd[1]: Started Wireless service.
Apr 05 15:18:12 rxps iwd[25839]: Wiphy: 0, Name: phy0
Apr 05 15:18:12 rxps iwd[25839]:         Bands: 2.4 GHz 5 GHz
Apr 05 15:18:12 rxps iwd[25839]:         Ciphers: CCMP TKIP BIP
Apr 05 15:18:12 rxps iwd[25839]:         Supported iftypes: ad-hoc station ap
Apr 05 15:18:12 rxps iwd[25839]: No ControlPortOverNL80211 setting, defaulting to True

...and in the journal

Apr 05 15:18:29 rxps kernel: wlp2s0: authenticate with a4:56:cc:05:d7:8e
Apr 05 15:18:29 rxps kernel: wlp2s0: send auth to a4:56:cc:05:d7:8e (try 1/3)
Apr 05 15:18:29 rxps kernel: wlp2s0: authenticated
Apr 05 15:18:29 rxps kernel: wlp2s0: associate with a4:56:cc:05:d7:8e (try 1/3)
Apr 05 15:18:29 rxps kernel: wlp2s0: RX AssocResp from a4:56:cc:05:d7:8e (capab=0x1511 status=0 aid=8)
Apr 05 15:18:29 rxps kernel: wlp2s0: associated
Apr 05 15:18:30 rxps systemd-networkd[319]: wlp2s0: Gained carrier
...

The new log message never appears in my journal, but from my observation other warning level logs do. I assume its because that conditional block is never entered but then why would this fix it?

anyway because now I think it might be relevant, here is some more info

$ uname -a
Linux rxps 5.0.6-arch1-1-ARCH #1 SMP PREEMPT Wed Apr 3 09:35:20 UTC 2019 x86_64 GNU/Linux
$ sudo lspci -v | sed -n '/Network/,/^$/ p'
02:00.0 Network controller: Intel Corporation Wireless 8265 / 8275 (rev 78)
	Subsystem: Intel Corporation Dual Band Wireless-AC 8265
	Flags: bus master, fast devsel, latency 0, IRQ 139
	Memory at edc00000 (64-bit, non-prefetchable) [size=8K]
	Capabilities: [c8] Power Management version 3
	Capabilities: [d0] MSI: Enable+ Count=1/1 Maskable- 64bit+
	Capabilities: [40] Express Endpoint, MSI 00
	Capabilities: [100] Advanced Error Reporting
	Capabilities: [140] Device Serial Number cc-2f-71-ff-ff-cd-ca-94
	Capabilities: [14c] Latency Tolerance Reporting
	Capabilities: [154] L1 PM Substates
	Kernel driver in use: iwlwifi
	Kernel modules: iwlwifi

Does anyone else care to try this hack? Does it work for you? Any idea what could be happening? Creating a proper fix for this is obviously above my head. Does anyone know where I can, or if I should, report my findings to a developer? I'm not very experienced with this stuff...

Last edited by Brocellous (2019-04-05 23:18:04)

Offline

#5 2019-04-05 23:05:05

loqs
Member
Registered: 2014-03-06
Posts: 17,196

Re: [Solved] Unable to connect to wireless using iwd 0.16

 	if (netdev->aborting)
+		l_warn("aborting");
 		return;

I think the issue is that with the addition of the l_warn the return is no longer guarded by the if i.e.

 	if (netdev->aborting)
		l_warn("aborting");
	return;

or

 	if (netdev->aborting)
		l_warn("aborting");
	else
 		return;

Last edited by loqs (2019-04-05 23:10:30)

Offline

#6 2019-04-05 23:08:31

Brocellous
Member
Registered: 2017-11-27
Posts: 134

Re: [Solved] Unable to connect to wireless using iwd 0.16

@loqs You are absolutely right, thanks. Strange that it works at all in that case. Thanks for your help. I think I'll just stick to 0.14 for now.

Offline

#7 2019-04-05 23:35:08

loqs
Member
Registered: 2014-03-06
Posts: 17,196

Offline

#8 2019-04-06 01:53:45

amish
Member
Registered: 2014-05-10
Posts: 470

Re: [Solved] Unable to connect to wireless using iwd 0.16

Brocellous wrote:

@loqs You are absolutely right, thanks. Strange that it works at all in that case. Thanks for your help. I think I'll just stick to 0.14 for now.

Your code worked because for our kind of router / AP, function netdev_associate_event() was supposed to just "return" without proceeding.

As @loqs pointed out, what actually happened is your code inadvertently "returned" regardless of any AP. (even for cases where it should not have returned), whereas you just wanted to log a warning.

	if (netdev->aborting)
		l_warn("aborting");

	// do nothing, just return
	return;

Hence in our case it started working.

Please mark the thread as "[Solved]"

Last edited by amish (2019-04-06 01:59:51)

Offline

Board footer

Powered by FluxBB