Package: network-manager Version: 1.6.2-3 Severity: normal Hello,
I have an interesting problem with network-manager: I am unable to switch between different WiFi networks (by selecting them in the systray list). However, if I first click on "Disconnect", and then select the new network, everything works fine. Here are the logs. I am currently connected to the "fred clever" network and attempting to switch to "Harpenden House": Sep 12 15:13:59 vostro.rath.org wpa_supplicant[2034]: wlan0: SME: Trying to authenticate with 00:1d:aa:9e:e6:e8 (SSID='Harpenden House' freq=2437 MHz) Sep 12 15:13:59 vostro.rath.org kernel: wlan0: authenticate with 00:1d:aa:9e:e6:e8 Sep 12 15:13:59 vostro.rath.org kernel: wlan0: send auth to 00:1d:aa:9e:e6:e8 (try 1/3) Sep 12 15:13:59 vostro.rath.org NetworkManager[1255]: <info> [1505225639.2394] device (wlan0): supplicant interface state: disconnected -> authenticating Sep 12 15:13:59 vostro.rath.org kernel: wlan0: authenticated Sep 12 15:13:59 vostro.rath.org kernel: iwlwifi 0000:03:00.0: No association and the time event is over already... Sep 12 15:13:59 vostro.rath.org kernel: wlan0: Connection to AP 00:1d:aa:9e:e6:e8 lost Sep 12 15:14:04 vostro.rath.org kernel: wlan0: aborting authentication with 00:1d:aa:9e:e6:e8 by local choice (Reason: 3=DEAUTH_LEAVING) Sep 12 15:14:04 vostro.rath.org NetworkManager[1255]: <info> [1505225644.2493] device (wlan0): supplicant interface state: authenticating -> disconnected Sep 12 15:14:04 vostro.rath.org NetworkManager[1255]: <info> [1505225644.3494] device (wlan0): supplicant interface state: disconnected -> scanningSep 12 15:13:59 vostro.rath.org wpa_supplicant[2034]: wlan0: SME: Trying to authenticate with 00:1d:aa:9e:e6:e8 (SSID='Harpenden House' freq=2437 MHz) Sep 12 15:13:59 vostro.rath.org kernel: wlan0: authenticate with 00:1d:aa:9e:e6:e8 Sep 12 15:13:59 vostro.rath.org kernel: wlan0: send auth to 00:1d:aa:9e:e6:e8 (try 1/3) Sep 12 15:13:59 vostro.rath.org NetworkManager[1255]: <info> [1505225639.2394] device (wlan0): supplicant interface state: disconnected -> authenticating Sep 12 15:13:59 vostro.rath.org kernel: wlan0: authenticated Sep 12 15:13:59 vostro.rath.org kernel: iwlwifi 0000:03:00.0: No association and the time event is over already... Sep 12 15:13:59 vostro.rath.org kernel: wlan0: Connection to AP 00:1d:aa:9e:e6:e8 lost Sep 12 15:14:04 vostro.rath.org kernel: wlan0: aborting authentication with 00:1d:aa:9e:e6:e8 by local choice (Reason: 3=DEAUTH_LEAVING) Sep 12 15:14:04 vostro.rath.org NetworkManager[1255]: <info> [1505225644.2493] device (wlan0): supplicant interface state: authenticating -> disconnected Sep 12 15:14:04 vostro.rath.org NetworkManager[1255]: <info> [1505225644.3494] device (wlan0): supplicant interface state: disconnected -> scanning ..now the system automatically reconnects to "fred clever". However, if I disconnect first: Sep 12 15:15:01 vostro.rath.org NetworkManager[1255]: <info> [1505225701.0735] device (wlan0): state change: activated -> deactivating (reason 'user-requested') [100 110 39] Sep 12 15:15:01 vostro.rath.org NetworkManager[1255]: <info> [1505225701.0766] audit: op="device-disconnect" interface="wlan0" ifindex=3 pid=2992 uid=1000 result="success" Sep 12 15:15:01 vostro.rath.org NetworkManager[1255]: <info> [1505225701.0769] device (wlan0): state change: deactivating -> disconnected (reason 'user-requested') [110 30 39] Sep 12 15:15:01 vostro.rath.org NetworkManager[1255]: <info> [1505225701.1092] dhcp4 (wlan0): canceled DHCP transaction, DHCP client pid 8512 Sep 12 15:15:01 vostro.rath.org NetworkManager[1255]: <info> [1505225701.1093] dhcp4 (wlan0): state changed bound -> done Sep 12 15:15:01 vostro.rath.org kernel: wlan0: deauthenticating from 00:1f:33:be:9a:c4 by local choice (Reason: 3=DEAUTH_LEAVING) Sep 12 15:15:01 vostro.rath.org wpa_supplicant[2034]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:1f:33:be:9a:c4 reason=3 locally_generated=1 Sep 12 15:15:01 vostro.rath.org wpa_supplicant[2034]: p2p-dev-wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD Sep 12 15:15:01 vostro.rath.org NetworkManager[1255]: <info> [1505225701.1292] device (wlan0): set-hw-addr: set MAC address to 46:03:C6:CE:E7:1F (scanning) Sep 12 15:15:01 vostro.rath.org kernel: IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready Sep 12 15:15:01 vostro.rath.org dbus[1228]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' Sep 12 15:15:01 vostro.rath.org NetworkManager[1255]: <warn> [1505225701.1328] sup-iface[0x55bbc3c2b010,wlan0]: connection disconnected (reason -3) Sep 12 15:15:01 vostro.rath.org NetworkManager[1255]: <info> [1505225701.1329] device (wlan0): supplicant interface state: completed -> disconnected Sep 12 15:15:01 vostro.rath.org systemd[1]: Starting Network Manager Script Dispatcher Service... Sep 12 15:15:01 vostro.rath.org dbus[1228]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher' Sep 12 15:15:01 vostro.rath.org systemd[1]: Started Network Manager Script Dispatcher Service. Sep 12 15:15:01 vostro.rath.org nm-dispatcher[8827]: req:1 'down' [wlan0]: new request (2 scripts) Sep 12 15:15:01 vostro.rath.org nm-dispatcher[8827]: req:1 'down' [wlan0]: start running ordered scripts... ...and then connect again to "Harpenden House", everything works fine Sep 12 15:15:10 vostro.rath.org NetworkManager[1255]: <info> [1505225710.8092] device (wlan0): Activation: starting connection 'Harpenden House' (ada42181-e8ff-483c-b6ca-35c182ac6e03) Sep 12 15:15:10 vostro.rath.org NetworkManager[1255]: <info> [1505225710.8094] audit: op="connection-activate" uuid="ada42181-e8ff-483c-b6ca-35c182ac6e03" name="Harpenden House" pid=2992 uid=1000 result="success" Sep 12 15:15:10 vostro.rath.org NetworkManager[1255]: <info> [1505225710.8096] device (wlan0): state change: disconnected -> prepare (reason 'none') [30 40 0] Sep 12 15:15:10 vostro.rath.org NetworkManager[1255]: <info> [1505225710.8128] device (wlan0): set-hw-addr: reset MAC address to AC:FD:CE:A2:C3:53 (preserve) Sep 12 15:15:10 vostro.rath.org NetworkManager[1255]: <info> [1505225710.8149] device (wlan0): state change: prepare -> config (reason 'none') [40 50 0] Sep 12 15:15:10 vostro.rath.org NetworkManager[1255]: <info> [1505225710.8151] device (wlan0): Activation: (wifi) access point 'Harpenden House' has security, but secrets are required. Sep 12 15:15:10 vostro.rath.org NetworkManager[1255]: <info> [1505225710.8151] device (wlan0): state change: config -> need-auth (reason 'none') [50 60 0] Sep 12 15:15:10 vostro.rath.org kernel: IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready Sep 12 15:15:10 vostro.rath.org NetworkManager[1255]: <info> [1505225710.8189] device (wlan0): state change: need-auth -> prepare (reason 'none') [60 40 0] Sep 12 15:15:10 vostro.rath.org NetworkManager[1255]: <info> [1505225710.8193] device (wlan0): state change: prepare -> config (reason 'none') [40 50 0] Sep 12 15:15:10 vostro.rath.org NetworkManager[1255]: <info> [1505225710.8195] device (wlan0): Activation: (wifi) connection 'Harpenden House' has security, and secrets exist. No new secrets needed. Sep 12 15:15:10 vostro.rath.org NetworkManager[1255]: <info> [1505225710.8195] Config: added 'ssid' value 'Harpenden House' Sep 12 15:15:10 vostro.rath.org NetworkManager[1255]: <info> [1505225710.8195] Config: added 'scan_ssid' value '1' Sep 12 15:15:10 vostro.rath.org NetworkManager[1255]: <info> [1505225710.8195] Config: added 'key_mgmt' value 'WPA-PSK' Sep 12 15:15:10 vostro.rath.org NetworkManager[1255]: <info> [1505225710.8196] Config: added 'psk' value '<hidden>' Sep 12 15:15:10 vostro.rath.org wpa_supplicant[2034]: wlan0: SME: Trying to authenticate with 00:1d:aa:9e:e6:e8 (SSID='Harpenden House' freq=2437 MHz) Sep 12 15:15:10 vostro.rath.org kernel: wlan0: authenticate with 00:1d:aa:9e:e6:e8 Sep 12 15:15:10 vostro.rath.org kernel: wlan0: send auth to 00:1d:aa:9e:e6:e8 (try 1/3) Sep 12 15:15:10 vostro.rath.org NetworkManager[1255]: <info> [1505225710.8788] device (wlan0): supplicant interface state: disconnected -> authenticating Sep 12 15:15:10 vostro.rath.org kernel: wlan0: authenticated Sep 12 15:15:10 vostro.rath.org wpa_supplicant[2034]: wlan0: Trying to associate with 00:1d:aa:9e:e6:e8 (SSID='Harpenden House' freq=2437 MHz) Sep 12 15:15:10 vostro.rath.org NetworkManager[1255]: <info> [1505225710.8849] device (wlan0): supplicant interface state: authenticating -> associating Sep 12 15:15:10 vostro.rath.org kernel: wlan0: associate with 00:1d:aa:9e:e6:e8 (try 1/3) Sep 12 15:15:10 vostro.rath.org kernel: wlan0: RX AssocResp from 00:1d:aa:9e:e6:e8 (capab=0x411 status=0 aid=1) Sep 12 15:15:10 vostro.rath.org wpa_supplicant[2034]: wlan0: Associated with 00:1d:aa:9e:e6:e8 Sep 12 15:15:10 vostro.rath.org kernel: wlan0: associated Sep 12 15:15:10 vostro.rath.org kernel: IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready Sep 12 15:15:10 vostro.rath.org wpa_supplicant[2034]: p2p-dev-wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=FR Sep 12 15:15:10 vostro.rath.org NetworkManager[1255]: <info> [1505225710.9087] device (wlan0): supplicant interface state: associating -> associated Sep 12 15:15:11 vostro.rath.org NetworkManager[1255]: <info> [1505225711.1133] device (wlan0): supplicant interface state: associated -> 4-way handshake Sep 12 15:15:17 vostro.rath.org kernel: wlan0: deauthenticated from 00:1d:aa:9e:e6:e8 (Reason: 15=4WAY_HANDSHAKE_TIMEOUT) Sep 12 15:15:17 vostro.rath.org wpa_supplicant[2034]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:1d:aa:9e:e6:e8 reason=15 Sep 12 15:15:17 vostro.rath.org wpa_supplicant[2034]: wlan0: WPA: 4-Way Handshake failed - pre-shared key may be incorrect Sep 12 15:15:17 vostro.rath.org NetworkManager[1255]: <warn> [1505225717.1477] sup-iface[0x55bbc3c2b010,wlan0]: connection disconnected (reason 15) Sep 12 15:15:17 vostro.rath.org wpa_supplicant[2034]: wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="Harpenden House" auth_failures=1 duration=10 reason=WRONG_KEY Sep 12 15:15:17 vostro.rath.org wpa_supplicant[2034]: p2p-dev-wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD Sep 12 15:15:17 vostro.rath.org NetworkManager[1255]: <info> [1505225717.1531] device (wlan0): supplicant interface state: 4-way handshake -> disconnected Sep 12 15:15:17 vostro.rath.org NetworkManager[1255]: <info> [1505225717.1538] device (wlan0): Activation: (wifi) disconnected during association, asking for new key Sep 12 15:15:17 vostro.rath.org NetworkManager[1255]: <info> [1505225717.1538] device (wlan0): state change: config -> need-auth (reason 'supplicant-disconnect') [50 60 8] Sep 12 15:15:17 vostro.rath.org NetworkManager[1255]: <info> [1505225717.2529] device (wlan0): supplicant interface state: disconnected -> inactive Sep 12 15:15:17 vostro.rath.org dbus[1228]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' Sep 12 15:15:17 vostro.rath.org systemd[1]: Starting Hostname Service... Sep 12 15:15:17 vostro.rath.org dbus[1228]: [system] Successfully activated service 'org.freedesktop.hostname1' Sep 12 15:15:17 vostro.rath.org systemd[1]: Started Hostname Service. Sep 12 15:15:19 vostro.rath.org NetworkManager[1255]: <info> [1505225719.0587] keyfile: update /etc/NetworkManager/system-connections/Harpenden House (ada42181-e8ff-483c-b6ca-35c182ac6e03,"Harpenden House") Sep 12 15:15:19 vostro.rath.org NetworkManager[1255]: <info> [1505225719.0592] device (wlan0): state change: need-auth -> prepare (reason 'none') [60 40 0] Sep 12 15:15:19 vostro.rath.org NetworkManager[1255]: <info> [1505225719.0596] device (wlan0): state change: prepare -> config (reason 'none') [40 50 0] Sep 12 15:15:19 vostro.rath.org NetworkManager[1255]: <info> [1505225719.0599] device (wlan0): Activation: (wifi) connection 'Harpenden House' has security, and secrets exist. No new secrets needed. Sep 12 15:15:19 vostro.rath.org NetworkManager[1255]: <info> [1505225719.0599] Config: added 'ssid' value 'Harpenden House' Sep 12 15:15:19 vostro.rath.org NetworkManager[1255]: <info> [1505225719.0599] Config: added 'scan_ssid' value '1' Sep 12 15:15:19 vostro.rath.org NetworkManager[1255]: <info> [1505225719.0599] Config: added 'key_mgmt' value 'WPA-PSK' Sep 12 15:15:19 vostro.rath.org NetworkManager[1255]: <info> [1505225719.0599] Config: added 'psk' value '<hidden>' Sep 12 15:15:19 vostro.rath.org NetworkManager[1255]: <info> [1505225719.0730] device (wlan0): supplicant interface state: inactive -> scanning Sep 12 15:15:19 vostro.rath.org wpa_supplicant[2034]: wlan0: SME: Trying to authenticate with 00:1d:aa:7e:49:34 (SSID='Harpenden House' freq=2462 MHz) Sep 12 15:15:19 vostro.rath.org kernel: wlan0: authenticate with 00:1d:aa:7e:49:34 Sep 12 15:15:19 vostro.rath.org NetworkManager[1255]: <info> [1505225719.1001] device (wlan0): supplicant interface state: scanning -> authenticating Sep 12 15:15:19 vostro.rath.org wpa_supplicant[2034]: wlan0: Trying to associate with 00:1d:aa:7e:49:34 (SSID='Harpenden House' freq=2462 MHz) Sep 12 15:15:19 vostro.rath.org kernel: wlan0: send auth to 00:1d:aa:7e:49:34 (try 1/3) Sep 12 15:15:19 vostro.rath.org kernel: wlan0: authenticated Sep 12 15:15:19 vostro.rath.org kernel: wlan0: associate with 00:1d:aa:7e:49:34 (try 1/3) Sep 12 15:15:19 vostro.rath.org NetworkManager[1255]: <info> [1505225719.1056] device (wlan0): supplicant interface state: authenticating -> associating Sep 12 15:15:19 vostro.rath.org kernel: wlan0: RX AssocResp from 00:1d:aa:7e:49:34 (capab=0x411 status=0 aid=1) Sep 12 15:15:19 vostro.rath.org wpa_supplicant[2034]: wlan0: Associated with 00:1d:aa:7e:49:34 Sep 12 15:15:19 vostro.rath.org kernel: wlan0: associated Sep 12 15:15:19 vostro.rath.org wpa_supplicant[2034]: p2p-dev-wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=FR Sep 12 15:15:19 vostro.rath.org NetworkManager[1255]: <info> [1505225719.1155] device (wlan0): supplicant interface state: associating -> associated Sep 12 15:15:19 vostro.rath.org NetworkManager[1255]: <info> [1505225719.3298] device (wlan0): supplicant interface state: associated -> 4-way handshake Sep 12 15:15:19 vostro.rath.org wpa_supplicant[2034]: wlan0: WPA: Key negotiation completed with 00:1d:aa:7e:49:34 [PTK=CCMP GTK=TKIP] Sep 12 15:15:19 vostro.rath.org wpa_supplicant[2034]: wlan0: CTRL-EVENT-CONNECTED - Connection to 00:1d:aa:7e:49:34 completed [id=0 id_str=] Sep 12 15:15:19 vostro.rath.org NetworkManager[1255]: <info> [1505225719.3478] device (wlan0): supplicant interface state: 4-way handshake -> completed Sep 12 15:15:19 vostro.rath.org NetworkManager[1255]: <info> [1505225719.3478] device (wlan0): Activation: (wifi) Stage 2 of 5 (Device Configure) successful. Connected to wireless network 'Harpenden House'. Sep 12 15:15:19 vostro.rath.org NetworkManager[1255]: <info> [1505225719.3478] device (wlan0): state change: config -> ip-config (reason 'none') [50 70 0] Sep 12 15:15:19 vostro.rath.org NetworkManager[1255]: <info> [1505225719.3481] dhcp4 (wlan0): activation: beginning transaction (timeout in 45 seconds) Sep 12 15:15:19 vostro.rath.org NetworkManager[1255]: <info> [1505225719.3490] dhcp4 (wlan0): dhclient started with pid 8893 Sep 12 15:15:19 vostro.rath.org dhclient[8893]: DHCPREQUEST of 192.168.1.30 on wlan0 to 255.255.255.255 port 67 Sep 12 15:15:19 vostro.rath.org dhclient[8893]: DHCPACK of 192.168.1.30 from 192.168.1.1 Sep 12 15:15:19 vostro.rath.org NetworkManager[1255]: <info> [1505225719.3942] dhcp4 (wlan0): address 192.168.1.30 Sep 12 15:15:19 vostro.rath.org NetworkManager[1255]: <info> [1505225719.3942] dhcp4 (wlan0): plen 24 (255.255.255.0) Sep 12 15:15:19 vostro.rath.org NetworkManager[1255]: <info> [1505225719.3942] dhcp4 (wlan0): gateway 192.168.1.1 Sep 12 15:15:19 vostro.rath.org NetworkManager[1255]: <info> [1505225719.3942] dhcp4 (wlan0): server identifier 192.168.1.1 Sep 12 15:15:19 vostro.rath.org NetworkManager[1255]: <info> [1505225719.3942] dhcp4 (wlan0): lease time 86400 Sep 12 15:15:19 vostro.rath.org NetworkManager[1255]: <info> [1505225719.3942] dhcp4 (wlan0): nameserver '194.72.0.98' Sep 12 15:15:19 vostro.rath.org NetworkManager[1255]: <info> [1505225719.3943] dhcp4 (wlan0): nameserver '194.74.65.68' Sep 12 15:15:19 vostro.rath.org NetworkManager[1255]: <info> [1505225719.3943] dhcp4 (wlan0): state changed unknown -> bound Sep 12 15:15:19 vostro.rath.org NetworkManager[1255]: <info> [1505225719.3953] device (wlan0): state change: ip-config -> ip-check (reason 'none') [70 80 0] Sep 12 15:15:19 vostro.rath.org NetworkManager[1255]: <info> [1505225719.3958] device (wlan0): state change: ip-check -> secondaries (reason 'none') [80 90 0] Sep 12 15:15:19 vostro.rath.org NetworkManager[1255]: <info> [1505225719.3961] device (wlan0): state change: secondaries -> activated (reason 'none') [90 100 0] Sep 12 15:15:19 vostro.rath.org dhclient[8893]: bound to 192.168.1.30 -- renewal in 38082 seconds. Sep 12 15:15:19 vostro.rath.org NetworkManager[1255]: <info> [1505225719.3998] policy: set 'Harpenden House' (wlan0) as default for IPv4 routing and DNS Sep 12 15:15:19 vostro.rath.org NetworkManager[1255]: <info> [1505225719.3999] device (wlan0): Activation: successful, device activated. Sep 12 15:15:19 vostro.rath.org dbus[1228]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' Sep 12 15:15:19 vostro.rath.org systemd[1]: Starting Network Manager Script Dispatcher Service... Sep 12 15:15:19 vostro.rath.org dbus[1228]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher' Sep 12 15:15:19 vostro.rath.org systemd[1]: Started Network Manager Script Dispatcher Service. Sep 12 15:15:19 vostro.rath.org nm-dispatcher[8902]: req:1 'up' [wlan0]: new request (2 scripts) Sep 12 15:15:19 vostro.rath.org nm-dispatcher[8902]: req:1 'up' [wlan0]: start running ordered scripts... -- System Information: Debian Release: 9.1 APT prefers stable-updates APT policy: (500, 'stable-updates'), (500, 'stable') Architecture: amd64 (x86_64) Kernel: Linux 4.9.0-3-amd64 (SMP w/8 CPU cores) Locale: LANG=en_US.UTF-8, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8), LANGUAGE=en_US.UTF-8 (charmap=UTF-8) Shell: /bin/sh linked to /bin/dash Init: systemd (via /run/systemd/system) Versions of packages network-manager depends on: ii adduser 3.115 ii dbus 1.10.18-1 ii init-system-helpers 1.48 ii libaudit1 1:2.6.7-2 ii libbluetooth3 5.43-2 ii libc6 2.24-11+deb9u1 ii libglib2.0-0 2.50.3-2 ii libgnutls30 3.5.8-5+deb9u2 ii libgudev-1.0-0 230-3 ii libjansson4 2.9-1 ii libmm-glib0 1.6.4-1 ii libndp0 1.6-1+b1 ii libnewt0.52 0.52.19-1+b1 ii libnl-3-200 3.2.27-2 ii libnm0 1.6.2-3 ii libpam-systemd 232-25+deb9u1 ii libpolkit-agent-1-0 0.105-18 ii libpolkit-gobject-1-0 0.105-18 ii libreadline7 7.0-3 ii libselinux1 2.6-3+b1 ii libsoup2.4-1 2.56.0-2+deb9u1 ii libsystemd0 232-25+deb9u1 ii libteamdctl0 1.26-1+b1 ii libuuid1 2.29.2-1 ii lsb-base 9.20161125 ii policykit-1 0.105-18 ii udev 232-25+deb9u1 ii wpasupplicant 2:2.4-1 Versions of packages network-manager recommends: ii crda 3.18-1 ii dnsmasq-base 2.76-5+b1 ii iptables 1.6.0+snapshot20161117-6 pn iputils-arping <none> ii isc-dhcp-client 4.3.5-3 pn modemmanager <none> pn ppp <none> Versions of packages network-manager suggests: pn libteam-utils <none> -- Configuration Files: /etc/NetworkManager/NetworkManager.conf changed: [main] plugins=ifupdown,keyfile dns=none [ifupdown] managed=false -- no debconf information
