I can't connect anymore to my home wifi since upgrading my machine from
Ubuntu 16.10 to Ubuntu 17.04.
The problem exists with kernel 4.10.0-20-generic from Ubuntu, and
remains with kernel 4.11.0-rc6 that I built from
linux-wireless. However, I can connect to a wifi network without
authentication. In the following logs, beguiled is the SSID of the
WPA-protected I can't connect to and FreeWifi the unprotected one for
which the connection succeeds.
I also copied the firmware files from
git://git.marvell.com/mwifiex-firmware.git, without success.
Here are the relevant lines from syslog. Network manager complains about
a "WRONG_KEY" but obviously I have triple checked the key, simplified
it, and checked that I can succcessfully connect to the same network
from my Android phone.
Let me know if you need anything else to investigate.
Julien.
--8<---------------cut here---------------start------------->8---
Apr 29 17:51:26 touco kernel: [ 1947.432039] usb 3-3: info: trying to associate to 'beguiled' bssid f4:ca:e5:ef:be:18
Apr 29 17:51:26 touco wpa_supplicant[1222]: wlx6045bdf646b4: Associated with f4:ca:e5:ef:be:18
Apr 29 17:51:26 touco wpa_supplicant[1222]: WMM AC: Missing IEs
Apr 29 17:51:26 touco NetworkManager[986]: <info> [1493481086.5692] device (wlx6045bdf646b4): supplicant interface state: disconnected -> associating
Apr 29 17:51:26 touco NetworkManager[986]: <info> [1493481086.5694] device (wlx6045bdf646b4): supplicant interface state: associating -> 4-way handshake
Apr 29 17:51:30 touco systemd[1]: Reloading OpenBSD Secure Shell server.
Apr 29 17:51:30 touco systemd[1]: Stopping LSB: Start NTP daemon...
Apr 29 17:51:30 touco systemd[1]: Reloaded OpenBSD Secure Shell server.
Apr 29 17:51:30 touco systemd[1]: Reloading.
Apr 29 17:51:30 touco kernel: [ 1951.459673] usb 3-3: info: successfully disconnected from f4:ca:e5:ef:be:18: reason code 2
Apr 29 17:51:30 touco kernel: [ 1951.459862] usb 3-3: CMD_RESP: cmd 0x10f error, result=0x2
Apr 29 17:51:30 touco wpa_supplicant[1222]: wlx6045bdf646b4: CTRL-EVENT-DISCONNECTED bssid=f4:ca:e5:ef:be:18 reason=2
Apr 29 17:51:30 touco wpa_supplicant[1222]: wlx6045bdf646b4: WPA: 4-Way Handshake failed - pre-shared key may be incorrect
Apr 29 17:51:30 touco wpa_supplicant[1222]: wlx6045bdf646b4: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="beguiled" auth_failures=1 duration=10 reason=WRONG_KEY
Apr 29 17:51:30 touco NetworkManager[986]: <warn> [1493481090.5439] sup-iface[0x5622b1f28570,wlx6045bdf646b4]: connection disconnected (reason 2)
Apr 29 17:51:30 touco wpa_supplicant[1222]: wlx6045bdf646b4: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
Apr 29 17:51:30 touco NetworkManager[986]: <info> [1493481090.5511] device (wlx6045bdf646b4): supplicant interface state: 4-way handshake -> disconnected
Apr 29 17:51:30 touco NetworkManager[986]: <info> [1493481090.5523] device (wlx6045bdf646b4): Activation: (wifi) disconnected during association, asking for new key
Apr 29 17:51:30 touco NetworkManager[986]: <info> [1493481090.5524] device (wlx6045bdf646b4): state change: config -> need-auth (reason 'supplicant-disconnect') [50 60 8]
Apr 29 17:51:30 touco NetworkManager[986]: <info> [1493481090.6487] device (wlx6045bdf646b4): supplicant interface state: disconnected -> scanning
Apr 29 17:51:33 touco NetworkManager[986]: <info> [1493481093.3528] device (wlx6045bdf646b4): supplicant interface state: scanning -> inactive
Apr 29 17:51:40 touco nm-dispatcher: req:2 'down' [wlx6045bdf646b4]: start running ordered scripts...
Apr 29 17:51:40 touco systemd[1]: Started LSB: Start NTP daemon.
Apr 29 17:51:52 touco NetworkManager[986]: <info> [1493481112.5363] keyfile: update /etc/NetworkManager/system-connections/beguiled (4ecc0776-046d-4f05-a324-19f5a8fe6853,"beguiled")
Apr 29 17:51:52 touco NetworkManager[986]: <info> [1493481112.5443] device (wlx6045bdf646b4): state change: need-auth -> prepare (reason 'none') [60 40 0]
Apr 29 17:51:52 touco NetworkManager[986]: <info> [1493481112.5454] device (wlx6045bdf646b4): state change: prepare -> config (reason 'none') [40 50 0]
Apr 29 17:51:52 touco NetworkManager[986]: <info> [1493481112.5457] device (wlx6045bdf646b4): Activation: (wifi) connection 'beguiled' has security, and secrets exist. No new secrets needed.
Apr 29 17:51:52 touco NetworkManager[986]: <info> [1493481112.5457] Config: added 'ssid' value 'beguiled'
Apr 29 17:51:52 touco NetworkManager[986]: <info> [1493481112.5458] Config: added 'scan_ssid' value '1'
Apr 29 17:51:52 touco NetworkManager[986]: <info> [1493481112.5458] Config: added 'key_mgmt' value 'WPA-PSK'
Apr 29 17:51:52 touco NetworkManager[986]: <info> [1493481112.5458] Config: added 'psk' value '<omitted>'
Apr 29 17:51:52 touco NetworkManager[986]: <info> [1493481112.5576] sup-iface[0x5622b1f28570,wlx6045bdf646b4]: config: set interface ap_scan to 1
Apr 29 17:51:52 touco NetworkManager[986]: <info> [1493481112.6146] device (wlx6045bdf646b4): supplicant interface state: inactive -> scanning
Apr 29 17:51:55 touco wpa_supplicant[1222]: wlx6045bdf646b4: Trying to associate with f4:ca:e5:ef:be:18 (SSID='beguiled' freq=2462 MHz)
Apr 29 17:51:55 touco kernel: [ 1976.214864] usb 3-3: info: trying to associate to 'beguiled' bssid f4:ca:e5:ef:be:18
Apr 29 17:51:55 touco wpa_supplicant[1222]: wlx6045bdf646b4: Associated with f4:ca:e5:ef:be:18
Apr 29 17:51:55 touco wpa_supplicant[1222]: WMM AC: Missing IEs
Apr 29 17:51:55 touco kernel: [ 1976.228198] usb 3-3: info: associated to bssid f4:ca:e5:ef:be:18 successfully
Apr 29 17:51:55 touco NetworkManager[986]: <info> [1493481115.3376] device (wlx6045bdf646b4): supplicant interface state: scanning -> associating
Apr 29 17:51:55 touco NetworkManager[986]: <info> [1493481115.3556] device (wlx6045bdf646b4): supplicant interface state: associating -> 4-way handshake
Apr 29 17:51:59 touco wpa_supplicant[1222]: wlx6045bdf646b4: CTRL-EVENT-DISCONNECTED bssid=f4:ca:e5:ef:be:18 reason=2
Apr 29 17:51:59 touco kernel: [ 1980.230780] usb 3-3: info: successfully disconnected from f4:ca:e5:ef:be:18: reason code 2
Apr 29 17:51:59 touco kernel: [ 1980.231075] usb 3-3: CMD_RESP: cmd 0x10f error, result=0x2
Apr 29 17:51:59 touco wpa_supplicant[1222]: wlx6045bdf646b4: WPA: 4-Way Handshake failed - pre-shared key may be incorrect
Apr 29 17:51:59 touco wpa_supplicant[1222]: wlx6045bdf646b4: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="beguiled" auth_failures=1 duration=10 reason=WRONG_KEY
Apr 29 17:51:59 touco NetworkManager[986]: <warn> [1493481119.3198] sup-iface[0x5622b1f28570,wlx6045bdf646b4]: connection disconnected (reason 2)
Apr 29 17:51:59 touco wpa_supplicant[1222]: wlx6045bdf646b4: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
Apr 29 17:51:59 touco NetworkManager[986]: <info> [1493481119.3268] device (wlx6045bdf646b4): supplicant interface state: 4-way handshake -> disconnected
Apr 29 17:51:59 touco NetworkManager[986]: <info> [1493481119.3289] device (wlx6045bdf646b4): Activation: (wifi) disconnected during association, asking for new key
Apr 29 17:51:59 touco NetworkManager[986]: <info> [1493481119.3292] device (wlx6045bdf646b4): state change: config -> need-auth (reason 'supplicant-disconnect') [50 60 8]
Apr 29 17:51:59 touco NetworkManager[986]: <info> [1493481119.4229] device (wlx6045bdf646b4): supplicant interface state: disconnected -> inactive
Apr 29 17:52:01 touco NetworkManager[986]: <warn> [1493481121.2329] device (wlx6045bdf646b4): User canceled the secrets request.
Apr 29 17:52:01 touco NetworkManager[986]: <info> [1493481121.2330] device (wlx6045bdf646b4): state change: need-auth -> failed (reason 'no-secrets') [60 120 7]
Apr 29 17:52:01 touco NetworkManager[986]: <warn> [1493481121.2335] device (wlx6045bdf646b4): Activation: failed for connection 'beguiled'
Apr 29 17:52:01 touco NetworkManager[986]: <info> [1493481121.2341] device (wlx6045bdf646b4): state change: failed -> disconnected (reason 'none') [120 30 0]
Apr 29 17:52:01 touco kernel: [ 1982.148580] IPv6: ADDRCONF(NETDEV_UP): wlx6045bdf646b4: link is not ready
Apr 29 17:52:01 touco NetworkManager[986]: <info> [1493481121.2368] device (wlx6045bdf646b4): set-hw-addr: set MAC address to 76:26:8D:50:C1:25 (scanning)
Apr 29 17:52:01 touco kernel: [ 1982.151031] IPv6: ADDRCONF(NETDEV_UP): wlx6045bdf646b4: link is not ready
Apr 29 17:52:01 touco NetworkManager[986]: <info> [1493481121.2405] policy: auto-activating connection 'FreeWifi'
Apr 29 17:52:01 touco NetworkManager[986]: <info> [1493481121.2415] device (wlx6045bdf646b4): Activation: starting connection 'FreeWifi' (0d348d83-b3b0-4ea0-894d-7b3a9e295392)
Apr 29 17:52:01 touco NetworkManager[986]: <info> [1493481121.2417] device (wlx6045bdf646b4): state change: disconnected -> prepare (reason 'none') [30 40 0]
Apr 29 17:52:01 touco wpa_supplicant[1222]: wlx6045bdf646b4: Failed to initiate sched scan
Apr 29 17:52:01 touco NetworkManager[986]: <info> [1493481121.2981] device (wlx6045bdf646b4): set-hw-addr: set-cloned MAC address to 60:45:BD:F6:46:B4 (permanent)
Apr 29 17:52:01 touco kernel: [ 1982.212280] IPv6: ADDRCONF(NETDEV_UP): wlx6045bdf646b4: link is not ready
Apr 29 17:52:01 touco NetworkManager[986]: <info> [1493481121.3081] device (wlx6045bdf646b4): state change: prepare -> config (reason 'none') [40 50 0]
Apr 29 17:52:01 touco NetworkManager[986]: <info> [1493481121.3089] device (wlx6045bdf646b4): Activation: (wifi) connection 'FreeWifi' requires no security. No secrets needed.
Apr 29 17:52:01 touco NetworkManager[986]: <info> [1493481121.3094] Config: added 'ssid' value 'FreeWifi'
Apr 29 17:52:01 touco NetworkManager[986]: <info> [1493481121.3098] Config: added 'scan_ssid' value '1'
Apr 29 17:52:01 touco NetworkManager[986]: <info> [1493481121.3098] Config: added 'key_mgmt' value 'NONE'
Apr 29 17:52:01 touco NetworkManager[986]: <info> [1493481121.3527] sup-iface[0x5622b1f28570,wlx6045bdf646b4]: config: set interface ap_scan to 1
Apr 29 17:52:01 touco wpa_supplicant[1222]: wlx6045bdf646b4: Trying to associate with f4:ca:e5:ef:be:19 (SSID='FreeWifi' freq=2462 MHz)
Apr 29 17:52:01 touco kernel: [ 1982.278390] usb 3-3: info: trying to associate to 'FreeWifi' bssid f4:ca:e5:ef:be:19
Apr 29 17:52:01 touco kernel: [ 1982.291327] usb 3-3: info: associated to bssid f4:ca:e5:ef:be:19 successfully
Apr 29 17:52:01 touco kernel: [ 1982.291453] IPv6: ADDRCONF(NETDEV_CHANGE): wlx6045bdf646b4: link becomes ready
Apr 29 17:52:01 touco wpa_supplicant[1222]: wlx6045bdf646b4: Associated with f4:ca:e5:ef:be:19
Apr 29 17:52:01 touco wpa_supplicant[1222]: wlx6045bdf646b4: CTRL-EVENT-CONNECTED - Connection to f4:ca:e5:ef:be:19 completed [id=0 id_str=]
Apr 29 17:52:01 touco wpa_supplicant[1222]: WMM AC: Missing IEs
Apr 29 17:52:01 touco NetworkManager[986]: <info> [1493481121.3817] device (wlx6045bdf646b4): supplicant interface state: inactive -> associating
Apr 29 17:52:01 touco NetworkManager[986]: <info> [1493481121.3853] device (wlx6045bdf646b4): supplicant interface state: associating -> completed
Apr 29 17:52:01 touco NetworkManager[986]: <info> [1493481121.3858] device (wlx6045bdf646b4): Activation: (wifi) Stage 2 of 5 (Device Configure) successful. Connected to wireless network 'FreeWifi'.
--8<---------------cut here---------------end--------------->8---
Julien Cubizolles <[email protected]> writes:
> I can't connect anymore to my home wifi since upgrading my machine from
> Ubuntu 16.10 to Ubuntu 17.04.
It turns out that the problem lies with NetworkManager, I managed to get
the wifi working with wpa_supplicant.
Julien.
Dan Williams <[email protected]> writes:
> On Wed, 2017-05-03 at 22:33 +0200, Julien Cubizolles wrote:
>> It turns out that the problem lies with NetworkManager, I managed to
>> get
>> the wifi working with wpa_supplicant.
>
> That's odd. Any idea what that was? MAC randomization?
I don't know if MAC randomization is supposed to be happen but ifconfig
always display the same MAC address for the wifi interface. Also the
same wifi router allows connections without secrets with another ssid,
and I have no problem connecting in this case.
> NM just uses the supplicant underneath, so there's no particular
> reason NM wouldn't work but wpa_supplicant itself would.
I'm using the following /etc/wpa_supplicant.conf file:
--8<---------------cut here---------------start------------->8---
ctrl_interface=/var/run/wpa_supplicant
ap_scan=1
network={
priority=2
ssid="beguiled"
psk="*****"
}
--8<---------------cut here---------------end--------------->8---
For the same ssid: NetworkManager uses the following
/etc/NetworkManager/system-connections/beguiled
--8<---------------cut here---------------start------------->8---
[connection]
id=beguiled
uuid=4ecc0776-046d-4f05-a324-19f5a8fe6853
type=wifi
permissions=
secondaries=
[wifi]
ssid=beguiled
[wifi-security]
psk=******
[ipv4]
dns-search=
method=auto
[ipv6]
addr-gen-mode=stable-privacy
dns-search=
method=auto
--8<---------------cut here---------------end--------------->8---
Here are the logs when NM fails:
--8<---------------cut here---------------start------------->8---
May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.8411] device (wlx6045bdf646b4): set-hw-addr: set MAC address to E2:D4:E4:49:77:59 (scanning)
May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.8433] manager: NetworkManager state is now DISCONNECTED
May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.8435] device (wlx6045bdf646b4): Activation: starting connection 'beguiled' (406e52d4-e98b-454b-8d32-ce69fee5e03f)
May 4 23:06:25 touco kernel: [ 58.255775] IPv6: ADDRCONF(NETDEV_UP): wlx6045bdf646b4: link is not ready
May 4 23:06:25 touco whoopsie[818]: [23:06:25] Cannot reach: https://daisy.ubuntu.com
May 4 23:06:25 touco nm-dispatcher: req:2 'down' [wlx6045bdf646b4]: new request (2 scripts)
May 4 23:06:25 touco nm-dispatcher: req:2 'down' [wlx6045bdf646b4]: start running ordered scripts...
May 4 23:06:25 touco whoopsie[818]: [23:06:25] Cannot reach: https://daisy.ubuntu.com
May 4 23:06:25 touco NetworkManager[833]: <warn> [1493931985.8711] sup-iface[0x5634f93244e0,wlx6045bdf646b4]: connection disconnected (reason -3)
May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.8712] device (wlx6045bdf646b4): supplicant interface state: completed -> disconnected
May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.8745] device (wlx6045bdf646b4): state change: disconnected -> prepare (reason 'none') [30 40 0]
May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.8747] manager: NetworkManager state is now CONNECTING
May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.9016] device (wlx6045bdf646b4): set-hw-addr: set-cloned MAC address to 60:45:BD:F6:46:B4 (permanent)
May 4 23:06:25 touco kernel: [ 58.316182] IPv6: ADDRCONF(NETDEV_UP): wlx6045bdf646b4: link is not ready
May 4 23:06:25 touco gsd-sharing[2450]: Failed to StopUnit service: GDBus.Error:org.freedesktop.systemd1.NoSuchUnit: Unit rygel.service not loaded.
May 4 23:06:25 touco gsd-sharing[2450]: Failed to StopUnit service: GDBus.Error:org.freedesktop.systemd1.NoSuchUnit: Unit vino-server.service not loaded.
May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.9314] device (wlx6045bdf646b4): state change: prepare -> config (reason 'none') [40 50 0]
May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.9322] device (wlx6045bdf646b4): Activation: (wifi) access point 'beguiled' has security, but secrets are required.
May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.9323] device (wlx6045bdf646b4): state change: config -> need-auth (reason 'none') [50 60 0]
May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.9394] device (wlx6045bdf646b4): state change: need-auth -> prepare (reason 'none') [60 40 0]
May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.9403] device (wlx6045bdf646b4): state change: prepare -> config (reason 'none') [40 50 0]
May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.9406] device (wlx6045bdf646b4): Activation: (wifi) connection 'beguiled' has security, and secrets exist. No new secrets needed.
May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.9406] Config: added 'ssid' value 'beguiled'
May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.9407] Config: added 'scan_ssid' value '1'
May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.9407] Config: added 'key_mgmt' value 'WPA-PSK'
May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.9407] Config: added 'auth_alg' value 'OPEN'
May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.9407] Config: added 'psk' value '<omitted>'
May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.9833] sup-iface[0x5634f93244e0,wlx6045bdf646b4]: config: set interface ap_scan to 1
May 4 23:06:26 touco wpa_supplicant[1171]: wlx6045bdf646b4: Trying to associate with f4:ca:e5:ef:be:18 (SSID='beguiled' freq=2462 MHz)
May 4 23:06:26 touco kernel: [ 58.421135] usb 3-3: info: trying to associate to 'beguiled' bssid f4:ca:e5:ef:be:18
May 4 23:06:26 touco kernel: [ 58.434898] usb 3-3: info: associated to bssid f4:ca:e5:ef:be:18 successfully
May 4 23:06:26 touco kernel: [ 58.434913] IPv6: ADDRCONF(NETDEV_CHANGE): wlx6045bdf646b4: link becomes ready
May 4 23:06:26 touco wpa_supplicant[1171]: wlx6045bdf646b4: Associated with f4:ca:e5:ef:be:18
May 4 23:06:26 touco wpa_supplicant[1171]: WMM AC: Missing IEs
May 4 23:06:26 touco NetworkManager[833]: <info> [1493931986.0221] device (wlx6045bdf646b4): supplicant interface state: disconnected -> associating
May 4 23:06:26 touco whoopsie[818]: [23:06:26] Cannot reach: https://daisy.ubuntu.com
May 4 23:06:26 touco NetworkManager[833]: <info> [1493931986.0265] device (wlx6045bdf646b4): supplicant interface state: associating -> 4-way handshake
May 4 23:06:26 touco tracker-miner-a[2529]: (Sparql buffer) Error in task 0 (file:///home/wilk/.local/share/applications/EmacsClient.desktop) of the array-update: UNIQUE constraint failed: nie:DataObject.nie:url (strerror of errno (not necessarily related): Ressource temporairement non disponible)
May 4 23:06:26 touco tracker-miner-a[2529]: Could not execute sparql: UNIQUE constraint failed: nie:DataObject.nie:url (strerror of errno (not necessarily related): Ressource temporairement non disponible)
May 4 23:06:27 touco ntpd[1990]: Deleting interface #3 wlx6045bdf646b4, 10.2.0.53#123, interface stats: received=0, sent=5, dropped=0, active_time=29 secs
May 4 23:06:27 touco ntpd[1990]: Deleting interface #5 wlx6045bdf646b4, fe80::6245:bdff:fef6:46b4%2#123, interface stats: received=0, sent=0, dropped=0, active_time=29 secs
May 4 23:06:28 touco gnome-shell[2189]: JS WARNING: [resource:///org/gnome/shell/ui/dash.js 760]: reference to undefined property oldApps[oldIndex]
May 4 23:06:28 touco dbus-daemon[1786]: Activating via systemd: service name='org.gnome.zeitgeist.Engine' unit='zeitgeist.service'
May 4 23:06:28 touco systemd[1774]: Starting Zeitgeist activity log service...
May 4 23:06:28 touco dbus-daemon[1786]: Activating via systemd: service name='org.gnome.zeitgeist.SimpleIndexer' unit='zeitgeist-fts.service'
May 4 23:06:28 touco dbus-daemon[1786]: Successfully activated service 'org.gnome.zeitgeist.Engine'
May 4 23:06:28 touco systemd[1774]: Started Zeitgeist activity log service.
May 4 23:06:28 touco systemd[1774]: Starting Zeitgeist full-text search indexer...
May 4 23:06:28 touco zeitgeist-daemon[2849]: #033[31m[21:06:28.606766 WARNING]#033[0m zeitgeist-daemon.vala:127: Unable to parse version info!
May 4 23:06:28 touco zeitgeist-daemon[2849]: #033[31m[21:06:28.608482 WARNING]#033[0m zeitgeist-daemon.vala:127: Unable to parse version info!
May 4 23:06:28 touco zeitgeist-daemon[2849]: #033[31m[21:06:28.631280 WARNING]#033[0m zeitgeist-daemon.vala:127: Unable to parse version info!
May 4 23:06:28 touco dbus-daemon[1786]: Successfully activated service 'org.gnome.zeitgeist.SimpleIndexer'
May 4 23:06:28 touco systemd[1774]: Started Zeitgeist full-text search indexer.
May 4 23:06:28 touco zeitgeist-datah[2857]: zeitgeist-datahub.vala:227: Unable to get name "org.gnome.zeitgeist.datahub" on the bus!
May 4 23:06:28 touco gnome-shell[2189]: JS WARNING: [resource:///org/gnome/shell/ui/appDisplay.js 1298]: reference to undefined property this.name
May 4 23:06:29 touco pulseaudio[2585]: [pulseaudio] module.c: After module unload, module 'module-null-sink' was still loaded!
May 4 23:06:30 touco wpa_supplicant[1171]: wlx6045bdf646b4: CTRL-EVENT-DISCONNECTED bssid=f4:ca:e5:ef:be:18 reason=2
May 4 23:06:30 touco kernel: [ 62.437145] usb 3-3: info: successfully disconnected from f4:ca:e5:ef:be:18: reason code 2
May 4 23:06:30 touco kernel: [ 62.437439] usb 3-3: CMD_RESP: cmd 0x10f error, result=0x2
May 4 23:06:30 touco wpa_supplicant[1171]: wlx6045bdf646b4: WPA: 4-Way Handshake failed - pre-shared key may be incorrect
May 4 23:06:30 touco NetworkManager[833]: <warn> [1493931990.0257] sup-iface[0x5634f93244e0,wlx6045bdf646b4]: connection disconnected (reason 2)
May 4 23:06:30 touco wpa_supplicant[1171]: wlx6045bdf646b4: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="beguiled" auth_failures=1 duration=10 reason=WRONG_KEY
May 4 23:06:30 touco NetworkManager[833]: <info> [1493931990.0340] device (wlx6045bdf646b4): supplicant interface state: 4-way handshake -> disconnected
May 4 23:06:30 touco wpa_supplicant[1171]: wlx6045bdf646b4: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
May 4 23:06:30 touco NetworkManager[833]: <info> [1493931990.0373] device (wlx6045bdf646b4): Activation: (wifi) disconnected during association, asking for new key
May 4 23:06:30 touco NetworkManager[833]: <info> [1493931990.0377] device (wlx6045bdf646b4): state change: config -> need-auth (reason 'supplicant-disconnect') [50 60 8]
May 4 23:06:30 touco NetworkManager[833]: <info> [1493931990.1292] device (wlx6045bdf646b4): supplicant interface state: disconnected -> scanning
May 4 23:06:30 touco org.gnome.Shell.desktop[2189]: Window manager warning: Invalid WM_TRANSIENT_FOR window 0x0 specified for 0x2600007 (Onboard).
May 4 23:06:31 touco kernel: [ 64.182891] ieee80211 phy0: mwifiex_cfg80211_sched_scan_start : Invalid Sched_scan parameters
May 4 23:06:31 touco wpa_supplicant[1171]: wlx6045bdf646b4: Failed to initiate sched scan
May 4 23:06:31 touco NetworkManager[833]: <info> [1493931991.7755] device (wlx6045bdf646b4): supplicant interface state: scanning -> inactive
May 4 23:06:32 touco NetworkManager[833]: <warn> [1493931992.4940] device (wlx6045bdf646b4): User canceled the secrets request.
May 4 23:06:32 touco NetworkManager[833]: <info> [1493931992.4941] device (wlx6045bdf646b4): state change: need-auth -> failed (reason 'no-secrets') [60 120 7]
May 4 23:06:32 touco NetworkManager[833]: <info> [1493931992.4944] manager: NetworkManager state is now DISCONNECTED
May 4 23:06:32 touco NetworkManager[833]: <warn> [1493931992.4950] device (wlx6045bdf646b4): Activation: failed for connection 'beguiled'
--8<---------------cut here---------------end--------------->8---
On Thu, 2017-05-04 at 23:27 +0200, Julien Cubizolles wrote:
> Dan Williams <[email protected]> writes:
>
> > On Wed, 2017-05-03 at 22:33 +0200, Julien Cubizolles wrote:
> > > It turns out that the problem lies with NetworkManager, I managed
> > > to
> > > get
> > > the wifi working with wpa_supplicant.
> >
> > That's odd. Any idea what that was? MAC randomization?
>
> I don't know if MAC randomization is supposed to be happen but
> ifconfig
> always display the same MAC address for the wifi interface. Also the
> same wifi router allows connections without secrets with another
> ssid,
> and I have no problem connecting in this case.
>
> > NM just uses the supplicant underneath, so there's no particular
> > reason NM wouldn't work but wpa_supplicant itself would.
>
> I'm using the following /etc/wpa_supplicant.conf file:
>
> --8<---------------cut here---------------start------------->8---
> ctrl_interface=/var/run/wpa_supplicant
> ap_scan=1
> network={
> priority=2
> ssid="beguiled"
> psk="*****"
Just to test, could you add:
auth_alg=OPEN
key_mgmt=WPA-PSK
scan_ssid=1
to the block and retry with the supplicant? I don't know why those
would make a difference but they might.
The reason code that is returned for the disconnect is unfortunately
WLAN_REASON_PREV_AUTH_NOT_VALID which doesn't tell us much.
Dan
> }
>
> --8<---------------cut here---------------end--------------->8---
>
> For the same ssid: NetworkManager uses the following
> /etc/NetworkManager/system-connections/beguiled
>
> --8<---------------cut here---------------start------------->8---
> [connection]
> id=beguiled
> uuid=4ecc0776-046d-4f05-a324-19f5a8fe6853
> type=wifi
> permissions=
> secondaries=
>
> [wifi]
> ssid=beguiled
>
> [wifi-security]
> psk=******
>
> [ipv4]
> dns-search=
> method=auto
>
> [ipv6]
> addr-gen-mode=stable-privacy
> dns-search=
> method=auto
> --8<---------------cut here---------------end--------------->8---
>
> Here are the logs when NM fails:
> --8<---------------cut here---------------start------------->8---
>
> May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.8411]
> device (wlx6045bdf646b4): set-hw-addr: set MAC address to
> E2:D4:E4:49:77:59 (scanning)
> May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.8433]
> manager: NetworkManager state is now DISCONNECTED
> May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.8435]
> device (wlx6045bdf646b4): Activation: starting connection 'beguiled'
> (406e52d4-e98b-454b-8d32-ce69fee5e03f)
> May 4 23:06:25 touco kernel: [ 58.255775] IPv6:
> ADDRCONF(NETDEV_UP): wlx6045bdf646b4: link is not ready
> May 4 23:06:25 touco whoopsie[818]: [23:06:25] Cannot reach: https:/
> /daisy.ubuntu.com
> May 4 23:06:25 touco nm-dispatcher: req:2 'down' [wlx6045bdf646b4]:
> new request (2 scripts)
> May 4 23:06:25 touco nm-dispatcher: req:2 'down' [wlx6045bdf646b4]:
> start running ordered scripts...
> May 4 23:06:25 touco whoopsie[818]: [23:06:25] Cannot reach: https:/
> /daisy.ubuntu.com
> May 4 23:06:25 touco NetworkManager[833]: <warn> [1493931985.8711]
> sup-iface[0x5634f93244e0,wlx6045bdf646b4]: connection disconnected
> (reason -3)
> May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.8712]
> device (wlx6045bdf646b4): supplicant interface state: completed ->
> disconnected
> May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.8745]
> device (wlx6045bdf646b4): state change: disconnected -> prepare
> (reason 'none') [30 40 0]
> May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.8747]
> manager: NetworkManager state is now CONNECTING
> May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.9016]
> device (wlx6045bdf646b4): set-hw-addr: set-cloned MAC address to
> 60:45:BD:F6:46:B4 (permanent)
> May 4 23:06:25 touco kernel: [ 58.316182] IPv6:
> ADDRCONF(NETDEV_UP): wlx6045bdf646b4: link is not ready
> May 4 23:06:25 touco gsd-sharing[2450]: Failed to StopUnit service:
> GDBus.Error:org.freedesktop.systemd1.NoSuchUnit: Unit rygel.service
> not loaded.
> May 4 23:06:25 touco gsd-sharing[2450]: Failed to StopUnit service:
> GDBus.Error:org.freedesktop.systemd1.NoSuchUnit: Unit vino-
> server.service not loaded.
> May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.9314]
> device (wlx6045bdf646b4): state change: prepare -> config (reason
> 'none') [40 50 0]
> May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.9322]
> device (wlx6045bdf646b4): Activation: (wifi) access point 'beguiled'
> has security, but secrets are required.
> May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.9323]
> device (wlx6045bdf646b4): state change: config -> need-auth (reason
> 'none') [50 60 0]
> May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.9394]
> device (wlx6045bdf646b4): state change: need-auth -> prepare (reason
> 'none') [60 40 0]
> May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.9403]
> device (wlx6045bdf646b4): state change: prepare -> config (reason
> 'none') [40 50 0]
> May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.9406]
> device (wlx6045bdf646b4): Activation: (wifi) connection 'beguiled'
> has security, and secrets exist. No new secrets needed.
> May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.9406]
> Config: added 'ssid' value 'beguiled'
> May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.9407]
> Config: added 'scan_ssid' value '1'
> May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.9407]
> Config: added 'key_mgmt' value 'WPA-PSK'
> May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.9407]
> Config: added 'auth_alg' value 'OPEN'
> May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.9407]
> Config: added 'psk' value '<omitted>'
> May 4 23:06:25 touco NetworkManager[833]: <info> [1493931985.9833]
> sup-iface[0x5634f93244e0,wlx6045bdf646b4]: config: set interface
> ap_scan to 1
> May 4 23:06:26 touco wpa_supplicant[1171]: wlx6045bdf646b4: Trying
> to associate with f4:ca:e5:ef:be:18 (SSID='beguiled' freq=2462 MHz)
> May 4 23:06:26 touco kernel: [ 58.421135] usb 3-3: info: trying to
> associate to 'beguiled' bssid f4:ca:e5:ef:be:18
> May 4 23:06:26 touco kernel: [ 58.434898] usb 3-3: info:
> associated to bssid f4:ca:e5:ef:be:18 successfully
> May 4 23:06:26 touco kernel: [ 58.434913] IPv6:
> ADDRCONF(NETDEV_CHANGE): wlx6045bdf646b4: link becomes ready
> May 4 23:06:26 touco wpa_supplicant[1171]: wlx6045bdf646b4:
> Associated with f4:ca:e5:ef:be:18
> May 4 23:06:26 touco wpa_supplicant[1171]: WMM AC: Missing IEs
> May 4 23:06:26 touco NetworkManager[833]: <info> [1493931986.0221]
> device (wlx6045bdf646b4): supplicant interface state: disconnected ->
> associating
> May 4 23:06:26 touco whoopsie[818]: [23:06:26] Cannot reach: https:/
> /daisy.ubuntu.com
> May 4 23:06:26 touco NetworkManager[833]: <info> [1493931986.0265]
> device (wlx6045bdf646b4): supplicant interface state: associating ->
> 4-way handshake
> May 4 23:06:26 touco tracker-miner-a[2529]: (Sparql buffer) Error
> in task 0
> (file:///home/wilk/.local/share/applications/EmacsClient.desktop) of
> the array-update: UNIQUE constraint failed: nie:DataObject.nie:url
> (strerror of errno (not necessarily related): Ressource
> temporairement non disponible)
> May 4 23:06:26 touco tracker-miner-a[2529]: Could not execute
> sparql: UNIQUE constraint failed: nie:DataObject.nie:url (strerror of
> errno (not necessarily related): Ressource temporairement non
> disponible)
> May 4 23:06:27 touco ntpd[1990]: Deleting interface #3
> wlx6045bdf646b4, 10.2.0.53#123, interface stats: received=0, sent=5,
> dropped=0, active_time=29 secs
> May 4 23:06:27 touco ntpd[1990]: Deleting interface #5
> wlx6045bdf646b4, fe80::6245:bdff:fef6:46b4%2#123, interface stats:
> received=0, sent=0, dropped=0, active_time=29 secs
> May 4 23:06:28 touco gnome-shell[2189]: JS WARNING:
> [resource:///org/gnome/shell/ui/dash.js 760]: reference to undefined
> property oldApps[oldIndex]
> May 4 23:06:28 touco dbus-daemon[1786]: Activating via systemd:
> service name='org.gnome.zeitgeist.Engine' unit='zeitgeist.service'
> May 4 23:06:28 touco systemd[1774]: Starting Zeitgeist activity log
> service...
> May 4 23:06:28 touco dbus-daemon[1786]: Activating via systemd:
> service name='org.gnome.zeitgeist.SimpleIndexer' unit='zeitgeist-
> fts.service'
> May 4 23:06:28 touco dbus-daemon[1786]: Successfully activated
> service 'org.gnome.zeitgeist.Engine'
> May 4 23:06:28 touco systemd[1774]: Started Zeitgeist activity log
> service.
> May 4 23:06:28 touco systemd[1774]: Starting Zeitgeist full-text
> search indexer...
> May 4 23:06:28 touco zeitgeist-daemon[2849]:
> #033[31m[21:06:28.606766 WARNING]#033[0m zeitgeist-daemon.vala:127:
> Unable to parse version info!
> May 4 23:06:28 touco zeitgeist-daemon[2849]:
> #033[31m[21:06:28.608482 WARNING]#033[0m zeitgeist-daemon.vala:127:
> Unable to parse version info!
> May 4 23:06:28 touco zeitgeist-daemon[2849]:
> #033[31m[21:06:28.631280 WARNING]#033[0m zeitgeist-daemon.vala:127:
> Unable to parse version info!
> May 4 23:06:28 touco dbus-daemon[1786]: Successfully activated
> service 'org.gnome.zeitgeist.SimpleIndexer'
> May 4 23:06:28 touco systemd[1774]: Started Zeitgeist full-text
> search indexer.
> May 4 23:06:28 touco zeitgeist-datah[2857]: zeitgeist-
> datahub.vala:227: Unable to get name "org.gnome.zeitgeist.datahub" on
> the bus!
> May 4 23:06:28 touco gnome-shell[2189]: JS WARNING:
> [resource:///org/gnome/shell/ui/appDisplay.js 1298]: reference to
> undefined property this.name
> May 4 23:06:29 touco pulseaudio[2585]: [pulseaudio] module.c: After
> module unload, module 'module-null-sink' was still loaded!
> May 4 23:06:30 touco wpa_supplicant[1171]: wlx6045bdf646b4: CTRL-
> EVENT-DISCONNECTED bssid=f4:ca:e5:ef:be:18 reason=2
> May 4 23:06:30 touco kernel: [ 62.437145] usb 3-3: info:
> successfully disconnected from f4:ca:e5:ef:be:18: reason code 2
> May 4 23:06:30 touco kernel: [ 62.437439] usb 3-3: CMD_RESP: cmd
> 0x10f error, result=0x2
> May 4 23:06:30 touco wpa_supplicant[1171]: wlx6045bdf646b4: WPA: 4-
> Way Handshake failed - pre-shared key may be incorrect
> May 4 23:06:30 touco NetworkManager[833]: <warn> [1493931990.0257]
> sup-iface[0x5634f93244e0,wlx6045bdf646b4]: connection disconnected
> (reason 2)
> May 4 23:06:30 touco wpa_supplicant[1171]: wlx6045bdf646b4: CTRL-
> EVENT-SSID-TEMP-DISABLED id=0 ssid="beguiled" auth_failures=1
> duration=10 reason=WRONG_KEY
> May 4 23:06:30 touco NetworkManager[833]: <info> [1493931990.0340]
> device (wlx6045bdf646b4): supplicant interface state: 4-way handshake
> -> disconnected
> May 4 23:06:30 touco wpa_supplicant[1171]: wlx6045bdf646b4: CTRL-
> EVENT-REGDOM-CHANGE init=CORE type=WORLD
> May 4 23:06:30 touco NetworkManager[833]: <info> [1493931990.0373]
> device (wlx6045bdf646b4): Activation: (wifi) disconnected during
> association, asking for new key
> May 4 23:06:30 touco NetworkManager[833]: <info> [1493931990.0377]
> device (wlx6045bdf646b4): state change: config -> need-auth (reason
> 'supplicant-disconnect') [50 60 8]
> May 4 23:06:30 touco NetworkManager[833]: <info> [1493931990.1292]
> device (wlx6045bdf646b4): supplicant interface state: disconnected ->
> scanning
> May 4 23:06:30 touco org.gnome.Shell.desktop[2189]: Window manager
> warning: Invalid WM_TRANSIENT_FOR window 0x0 specified for 0x2600007
> (Onboard).
> May 4 23:06:31 touco kernel: [ 64.182891] ieee80211 phy0:
> mwifiex_cfg80211_sched_scan_start : Invalid Sched_scan parameters
> May 4 23:06:31 touco wpa_supplicant[1171]: wlx6045bdf646b4: Failed
> to initiate sched scan
> May 4 23:06:31 touco NetworkManager[833]: <info> [1493931991.7755]
> device (wlx6045bdf646b4): supplicant interface state: scanning ->
> inactive
> May 4 23:06:32 touco NetworkManager[833]: <warn> [1493931992.4940]
> device (wlx6045bdf646b4): User canceled the secrets request.
> May 4 23:06:32 touco NetworkManager[833]: <info> [1493931992.4941]
> device (wlx6045bdf646b4): state change: need-auth -> failed (reason
> 'no-secrets') [60 120 7]
> May 4 23:06:32 touco NetworkManager[833]: <info> [1493931992.4944]
> manager: NetworkManager state is now DISCONNECTED
> May 4 23:06:32 touco NetworkManager[833]: <warn> [1493931992.4950]
> device (wlx6045bdf646b4): Activation: failed for connection
> 'beguiled'
> --8<---------------cut here---------------end--------------->8---
On Sat, 2017-05-06 at 10:41 +0200, Julien Cubizolles wrote:
> Dan Williams <[email protected]> writes:
>
>
> > Just to test, could you add:
> >
> > auth_alg=OPEN
> > key_mgmt=WPA-PSK
> > scan_ssid=1
> >
> > to the block and retry with the supplicant? I don't know why those
> > would make a difference but they might.
>
> They don't: wpa_supplicant still connects with these settings.
Ok, at this point the only thing I can think of is the MAC
randomization that NM has. Please see:
https://blogs.gnome.org/thaller/2016/08/26/mac-address-spoofing-in-networkmanager-1-4-0/
and look at the section "Randomization during Wi-Fi scanning" where it
says:
----
This default behavior can be disabled with a global configuration
option in NetworkManager.conf:
[device]
wifi.scan-rand-mac-address=no
----
if you set that, and restart NetworkManager, does that magically make
things work?
Dan
On Sat, 2017-05-06 at 22:22 +0200, Julien Cubizolles wrote:
> Dan Williams <[email protected]> writes:
>
>
> > Ok, at this point the only thing I can think of is the MAC
> > randomization that NM has. Please see:
> >
> > https://blogs.gnome.org/thaller/2016/08/26/mac-address-spoofing-in-
> > networkmanager-1-4-0/
> >
> > and look at the section "Randomization during Wi-Fi scanning" where
> > it
> > says:
> >
> > ----
> > This default behavior can be disabled with a global configuration
> > option in NetworkManager.conf:
> >
> > [device]
> > wifi.scan-rand-mac-address=no
> > ----
> >
> > if you set that, and restart NetworkManager, does that magically
> > make
> > things work?
>
> Yes! It's now working fine, thanks a lot. I have my wifi AP set to
> only
> accept a whitelist of MAC addresses so it makes sense that I can't
> connect if the MAC address is random. I'll disable the randomization
> for
> now on.
Well, ideally you wouldn't have to do this, but we haven't quite
figured out whether it's a bug in the way NM does randomization or
whether the drivers that require this switch (there are a few) are just
broken somehow.
Dan
On Wed, 2017-05-03 at 22:33 +0200, Julien Cubizolles wrote:
> Julien Cubizolles <[email protected]> writes:
>
> > I can't connect anymore to my home wifi since upgrading my machine
> > from
> > Ubuntu 16.10 to Ubuntu 17.04.
>
> It turns out that the problem lies with NetworkManager, I managed to
> get
> the wifi working with wpa_supplicant.
That's odd. Any idea what that was? MAC randomization? NM just uses
the supplicant underneath, so there's no particular reason NM wouldn't
work but wpa_supplicant itself would.
Dan
Dan Williams <[email protected]> writes:
> Ok, at this point the only thing I can think of is the MAC
> randomization that NM has. Please see:
>
> https://blogs.gnome.org/thaller/2016/08/26/mac-address-spoofing-in-networkmanager-1-4-0/
>
> and look at the section "Randomization during Wi-Fi scanning" where it
> says:
>
> ----
> This default behavior can be disabled with a global configuration
> option in NetworkManager.conf:
>
> [device]
> wifi.scan-rand-mac-address=no
> ----
>
> if you set that, and restart NetworkManager, does that magically make
> things work?
Yes! It's now working fine, thanks a lot. I have my wifi AP set to only
accept a whitelist of MAC addresses so it makes sense that I can't
connect if the MAC address is random. I'll disable the randomization for
now on.
Julien.
Dan Williams <[email protected]> writes:
> Just to test, could you add:
>
> auth_alg=OPEN
> key_mgmt=WPA-PSK
> scan_ssid=1
>
> to the block and retry with the supplicant? I don't know why those
> would make a difference but they might.
They don't: wpa_supplicant still connects with these settings.