bug#38667: Network-Manager (sometimes) fails reconnecting to network aut

bug-guix
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]
bug#38667: Network-Manager (sometimes) fails reconnecting to network aut

From:	Maxim Cournoyer
Subject:	bug#38667: Network-Manager (sometimes) fails reconnecting to network automatically
Date:	Wed, 18 Dec 2019 23:23:51 -0500
I was bit by this problem a couple times, so I'm reporting it here.

I don't know what causes it or how to reproduce it, but the following
/var/log/messages was captured at the time it occurred:

--8<---------------cut here---------------start------------->8---
Dec 14 14:31:36 localhost wpa_supplicant[297]: wlp18s0: WPA: Group rekeying 
completed with 20:4e:7f:85:ab:13 [GTK=CCMP]
Dec 14 14:41:36 localhost wpa_supplicant[297]: wlp18s0: WPA: Group rekeying 
completed with 20:4e:7f:85:ab:13 [GTK=CCMP]
Dec 14 14:51:36 localhost wpa_supplicant[297]: wlp18s0: WPA: Group rekeying 
completed with 20:4e:7f:85:ab:13 [GTK=CCMP]
Dec 14 15:01:36 localhost wpa_supplicant[297]: wlp18s0: WPA: Group rekeying 
completed with 20:4e:7f:85:ab:13 [GTK=CCMP]
Dec 14 15:01:40 localhost vmunix: [2511470.602960] wlp18s0: deauthenticated 
from 20:4e:7f:85:ab:13 (Reason: 2=PREV_AUTH_NOT_VALID)
Dec 14 15:01:40 localhost wpa_supplicant[297]: wlp18s0: CTRL-EVENT-DISCONNECTED 
bssid=20:4e:7f:85:ab:13 reason=2
Dec 14 15:01:40 localhost wpa_supplicant[297]: dbus: wpa_dbus_property_changed: 
no property SessionLength in object /fi/w1/wpa_supplicant1/Interfaces/0
Dec 14 15:01:40 localhost wpa_supplicant[297]: wlp18s0: 
CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
Dec 14 15:01:40 localhost NetworkManager[298]: <warn>  [1576353700.9145] 
sup-iface[0x20f30d0,wlp18s0]: connection disconnected (reason 2)
Dec 14 15:01:40 localhost NetworkManager[298]: <info>  [1576353700.9199] device 
(wlp18s0): supplicant interface state: completed -> disconnected
Dec 14 15:01:41 localhost NetworkManager[298]: <info>  [1576353701.0209] device 
(wlp18s0): supplicant interface state: disconnected -> scanning
Dec 14 15:01:42 localhost vmunix: [2511471.859993] wlp18s0: authenticate with 
20:4e:7f:85:ab:13
Dec 14 15:01:42 localhost wpa_supplicant[297]: wlp18s0: SME: Trying to 
authenticate with 20:4e:7f:85:ab:13 (SSID='MY-AP-NAME' freq=2422 MHz)
Dec 14 15:01:42 localhost vmunix: [2511471.873637] wlp18s0: send auth to 
20:4e:7f:85:ab:13 (try 1/3)
Dec 14 15:01:42 localhost NetworkManager[298]: <info>  [1576353702.0864] device 
(wlp18s0): supplicant interface state: scanning -> authenticating
Dec 14 15:01:42 localhost vmunix: [2511471.876696] wlp18s0: authenticated
Dec 14 15:01:42 localhost wpa_supplicant[297]: wlp18s0: Trying to associate 
with 20:4e:7f:85:ab:13 (SSID='MY-AP-NAME' freq=2422 MHz)
Dec 14 15:01:42 localhost vmunix: [2511471.883450] wlp18s0: associate with 
20:4e:7f:85:ab:13 (try 1/3)
Dec 14 15:01:42 localhost NetworkManager[298]: <info>  [1576353702.0970] device 
(wlp18s0): supplicant interface state: authenticating -> associating
Dec 14 15:01:42 localhost vmunix: [2511471.887256] wlp18s0: RX AssocResp from 
20:4e:7f:85:ab:13 (capab=0x431 status=0 aid=2)
Dec 14 15:01:42 localhost vmunix: [2511471.887498] wlp18s0: associated
Dec 14 15:01:42 localhost wpa_supplicant[297]: wlp18s0: Associated with 
20:4e:7f:85:ab:13
Dec 14 15:01:42 localhost wpa_supplicant[297]: wlp18s0: 
CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Dec 14 15:01:42 localhost NetworkManager[298]: <info>  [1576353702.1100] device 
(wlp18s0): supplicant interface state: associating -> 4-way handshake
Dec 14 15:01:42 localhost wpa_supplicant[297]: wlp18s0: 
CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=CA
Dec 14 15:01:43 localhost ntpd[299]: Deleting interface #141 wlp18s0, 
192.168.10.159#123, interface stats: received=1435, sent=1440, dropped=0, 
active_time=144600 secs
Dec 14 15:01:43 localhost ntpd[299]: 192.99.2.172 local addr 192.168.10.159 -> 
<null>
Dec 14 15:01:43 localhost ntpd[299]: 54.39.13.155 local addr 192.168.10.159 -> 
<null>
Dec 14 15:01:43 localhost ntpd[299]: 149.56.121.16 local addr 192.168.10.159 -> 
<null>
Dec 14 15:01:43 localhost ntpd[299]: 149.56.27.12 local addr 192.168.10.159 -> 
<null>
Dec 14 15:01:43 localhost ntpd[299]: 192.99.2.8 local addr 192.168.10.159 -> 
<null>
Dec 14 15:01:43 localhost ntpd[299]: 54.39.23.64 local addr 192.168.10.159 -> 
<null>
Dec 14 15:01:43 localhost ntpd[299]: 50.101.251.61 local addr 192.168.10.159 -> 
<null>
Dec 14 15:01:43 localhost ntpd[299]: 162.159.200.1 local addr 192.168.10.159 -> 
<null>
Dec 14 15:01:43 localhost ntpd[299]: 172.105.3.89 local addr 192.168.10.159 -> 
<null>
Dec 14 15:01:43 localhost ntpd[299]: Deleting interface #142 wlp18s0, 
fdb5:f1eb:7663::2a3#123, interface stats: received=0, sent=0, dropped=0, 
active_time=144600 secs
Dec 14 15:01:43 localhost ntpd[299]: Deleting interface #143 wlp18s0, 
fdb5:f1eb:7663:0:3f6a:8955:6109:580#123, interface stats: received=0, sent=0, 
dropped=0, active_time=144600 secs
Dec 14 15:01:43 localhost ntpd[299]: Deleting interface #144 wlp18s0, 
fe80::105:d3cb:cb27:ba08%3#123, interface stats: received=0, sent=0, dropped=0, 
active_time=144600 secs
Dec 14 15:01:44 localhost wpa_supplicant[297]: wlp18s0: WPA: Key negotiation 
completed with 20:4e:7f:85:ab:13 [PTK=CCMP GTK=CCMP]
Dec 14 15:01:44 localhost wpa_supplicant[297]: wlp18s0: CTRL-EVENT-CONNECTED - 
Connection to 20:4e:7f:85:ab:13 completed [id=0 id_str=]
Dec 14 15:01:44 localhost wpa_supplicant[297]: wlp18s0: 
CTRL-EVENT-SIGNAL-CHANGE above=1 signal=-69 noise=-91 txrate=1000
Dec 14 15:01:44 localhost NetworkManager[298]: <info>  [1576353704.1193] device 
(wlp18s0): supplicant interface state: 4-way handshake -> completed
Dec 14 15:01:45 localhost ntpd[299]: Listen normally on 145 wlp18s0 
192.168.10.159:123
Dec 14 15:01:45 localhost ntpd[299]: Listen normally on 146 wlp18s0 
[fdb5:f1eb:7663::2a3]:123
Dec 14 15:01:45 localhost ntpd[299]: Listen normally on 147 wlp18s0 
[fdb5:f1eb:7663:0:3f6a:8955:6109:580]:123
Dec 14 15:01:45 localhost ntpd[299]: Listen normally on 148 wlp18s0 
[fe80::105:d3cb:cb27:ba08%3]:123
Dec 14 15:02:38 localhost wpa_supplicant[297]: wlp18s0: 
CTRL-EVENT-SIGNAL-CHANGE above=1 signal=-62 noise=-91 txrate=52000
Dec 14 15:11:36 localhost wpa_supplicant[297]: wlp18s0: WPA: Group rekeying 
completed with 20:4e:7f:85:ab:13 [GTK=CCMP]
Dec 14 15:21:36 localhost wpa_supplicant[297]: wlp18s0: WPA: Group rekeying 
completed with 20:4e:7f:85:ab:13 [GTK=CCMP]
Dec 14 15:31:36 localhost wpa_supplicant[297]: wlp18s0: WPA: Group rekeying 
completed with 20:4e:7f:85:ab:13 [GTK=CCMP]
Dec 14 15:41:36 localhost wpa_supplicant[297]: wlp18s0: WPA: Group rekeying 
completed with 20:4e:7f:85:ab:13 [GTK=CCMP]
Dec 14 15:51:12 localhost sshd[10646]: error: kex_exchange_identification: 
banner line contains invalid characters
Dec 14 15:51:36 localhost wpa_supplicant[297]: wlp18s0: WPA: Group rekeying 
completed with 20:4e:7f:85:ab:13 [GTK=CCMP]
Dec 14 16:01:36 localhost wpa_supplicant[297]: wlp18s0: WPA: Group rekeying 
completed with 20:4e:7f:85:ab:13 [GTK=CCMP]
Dec 14 16:11:36 localhost wpa_supplicant[297]: wlp18s0: WPA: Group rekeying 
completed with 20:4e:7f:85:ab:13 [GTK=CCMP]
Dec 14 16:21:36 localhost wpa_supplicant[297]: wlp18s0: WPA: Group rekeying 
completed with 20:4e:7f:85:ab:13 [GTK=CCMP]
Dec 14 16:23:20 localhost dhclient: PRC: Renewing lease on wlp18s0.
Dec 14 16:23:20 localhost dhclient: XMT: Renew on wlp18s0, interval 10350ms.
Dec 14 16:23:20 localhost dhclient: RCV: Reply message on wlp18s0 from 
fe80::204e:7fff:fe85:ab13.
Dec 14 16:23:20 localhost NetworkManager[298]: <info>  [1576358600.9195] dhcp6 
(wlp18s0):   valid_lft 4294967295
Dec 14 16:23:20 localhost NetworkManager[298]: <info>  [1576358600.9196] dhcp6 
(wlp18s0):   preferred_lft 4294967295
Dec 14 16:23:20 localhost NetworkManager[298]: <info>  [1576358600.9196] dhcp6 
(wlp18s0):   address fdb5:f1eb:7663::2a3
Dec 14 16:23:20 localhost NetworkManager[298]: <info>  [1576358600.9196] dhcp6 
(wlp18s0):   nameserver 'fdb5:f1eb:7663::1'
Dec 14 16:23:20 localhost NetworkManager[298]: <info>  [1576358600.9197] dhcp6 
(wlp18s0): state changed bound -> bound, event ID="da:5d:2f:2f|1576358600"
Dec 14 16:31:36 localhost wpa_supplicant[297]: wlp18s0: WPA: Group rekeying 
completed with 20:4e:7f:85:ab:13 [GTK=CCMP]
Dec 14 16:31:40 localhost vmunix: [2516870.552438] wlp18s0: deauthenticated 
from 20:4e:7f:85:ab:13 (Reason: 2=PREV_AUTH_NOT_VALID)
Dec 14 16:31:40 localhost wpa_supplicant[297]: wlp18s0: CTRL-EVENT-DISCONNECTED 
bssid=20:4e:7f:85:ab:13 reason=2
Dec 14 16:31:40 localhost wpa_supplicant[297]: dbus: wpa_dbus_property_changed: 
no property SessionLength in object /fi/w1/wpa_supplicant1/Interfaces/0
Dec 14 16:31:40 localhost wpa_supplicant[297]: wlp18s0: 
CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
Dec 14 16:31:40 localhost NetworkManager[298]: <warn>  [1576359100.9141] 
sup-iface[0x20f30d0,wlp18s0]: connection disconnected (reason 2)
Dec 14 16:31:40 localhost NetworkManager[298]: <info>  [1576359100.9198] device 
(wlp18s0): supplicant interface state: completed -> disconnected
Dec 14 16:31:41 localhost NetworkManager[298]: <info>  [1576359101.0208] device 
(wlp18s0): supplicant interface state: disconnected -> scanning
Dec 14 16:31:42 localhost vmunix: [2516871.785618] wlp18s0: authenticate with 
20:4e:7f:85:ab:13
Dec 14 16:31:42 localhost wpa_supplicant[297]: wlp18s0: SME: Trying to 
authenticate with 20:4e:7f:85:ab:13 (SSID='MY-AP-NAME' freq=2422 MHz)
Dec 14 16:31:42 localhost vmunix: [2516871.799005] wlp18s0: send auth to 
20:4e:7f:85:ab:13 (try 1/3)
Dec 14 16:31:42 localhost NetworkManager[298]: <info>  [1576359102.0854] device 
(wlp18s0): supplicant interface state: scanning -> authenticating
Dec 14 16:31:42 localhost vmunix: [2516871.812655] wlp18s0: authenticated
Dec 14 16:31:42 localhost wpa_supplicant[297]: wlp18s0: Trying to associate 
with 20:4e:7f:85:ab:13 (SSID='MY-AP-NAME' freq=2422 MHz)
Dec 14 16:31:42 localhost NetworkManager[298]: <info>  [1576359102.0994] device 
(wlp18s0): supplicant interface state: authenticating -> associating
Dec 14 16:31:42 localhost vmunix: [2516871.816776] wlp18s0: associate with 
20:4e:7f:85:ab:13 (try 1/3)
Dec 14 16:31:42 localhost vmunix: [2516871.891608] wlp18s0: RX AssocResp from 
20:4e:7f:85:ab:13 (capab=0x431 status=0 aid=2)
Dec 14 16:31:42 localhost vmunix: [2516871.891773] wlp18s0: associated
Dec 14 16:31:42 localhost wpa_supplicant[297]: wlp18s0: Associated with 
20:4e:7f:85:ab:13
Dec 14 16:31:42 localhost wpa_supplicant[297]: wlp18s0: 
CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Dec 14 16:31:42 localhost NetworkManager[298]: <info>  [1576359102.1836] device 
(wlp18s0): supplicant interface state: associating -> 4-way handshake
Dec 14 16:31:42 localhost wpa_supplicant[297]: wlp18s0: 
CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=CA
Dec 14 16:31:43 localhost ntpd[299]: Deleting interface #145 wlp18s0, 
192.168.10.159#123, interface stats: received=107, sent=107, dropped=0, 
active_time=5398 secs
Dec 14 16:31:43 localhost ntpd[299]: 192.99.2.172 local addr 192.168.10.159 -> 
<null>
Dec 14 16:31:43 localhost ntpd[299]: 54.39.13.155 local addr 192.168.10.159 -> 
<null>
Dec 14 16:31:43 localhost ntpd[299]: 149.56.121.16 local addr 192.168.10.159 -> 
<null>
Dec 14 16:31:43 localhost ntpd[299]: 149.56.27.12 local addr 192.168.10.159 -> 
<null>
Dec 14 16:31:43 localhost ntpd[299]: 192.99.2.8 local addr 192.168.10.159 -> 
<null>
Dec 14 16:31:43 localhost ntpd[299]: 54.39.23.64 local addr 192.168.10.159 -> 
<null>
Dec 14 16:31:43 localhost ntpd[299]: 50.101.251.61 local addr 192.168.10.159 -> 
<null>
Dec 14 16:31:43 localhost ntpd[299]: 162.159.200.1 local addr 192.168.10.159 -> 
<null>
Dec 14 16:31:43 localhost ntpd[299]: 172.105.3.89 local addr 192.168.10.159 -> 
<null>
Dec 14 16:31:43 localhost ntpd[299]: Deleting interface #146 wlp18s0, 
fdb5:f1eb:7663::2a3#123, interface stats: received=0, sent=0, dropped=0, 
active_time=5398 secs
Dec 14 16:31:43 localhost ntpd[299]: Deleting interface #147 wlp18s0, 
fdb5:f1eb:7663:0:3f6a:8955:6109:580#123, interface stats: received=0, sent=0, 
dropped=0, active_time=5398 secs
Dec 14 16:31:43 localhost ntpd[299]: Deleting interface #148 wlp18s0, 
fe80::105:d3cb:cb27:ba08%3#123, interface stats: received=0, sent=0, dropped=0, 
active_time=5398 secs
Dec 14 16:31:46 localhost vmunix: [2516875.929689] wlp18s0: deauthenticated 
from 20:4e:7f:85:ab:13 (Reason: 2=PREV_AUTH_NOT_VALID)
Dec 14 16:31:46 localhost wpa_supplicant[297]: wlp18s0: CTRL-EVENT-DISCONNECTED 
bssid=20:4e:7f:85:ab:13 reason=2
Dec 14 16:31:46 localhost wpa_supplicant[297]: wlp18s0: WPA: 4-Way Handshake 
failed - pre-shared key may be incorrect
Dec 14 16:31:46 localhost wpa_supplicant[297]: wlp18s0: 
CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="MY-AP-NAME" auth_failures=1 
duration=10 reason=WRONG_KEY
Dec 14 16:31:46 localhost wpa_supplicant[297]: dbus: wpa_dbus_property_changed: 
no property SessionLength in object /fi/w1/wpa_supplicant1/Interfaces/0
Dec 14 16:31:46 localhost wpa_supplicant[297]: wlp18s0: 
CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
Dec 14 16:31:46 localhost NetworkManager[298]: <warn>  [1576359106.2542] 
sup-iface[0x20f30d0,wlp18s0]: connection disconnected (reason 2)
Dec 14 16:31:46 localhost NetworkManager[298]: <info>  [1576359106.2594] device 
(wlp18s0): supplicant interface state: 4-way handshake -> disconnected
Dec 14 16:31:46 localhost NetworkManager[298]: <info>  [1576359106.2604] device 
(wlp18s0): Activation: (wifi) disconnected during association, asking for new 
key
Dec 14 16:31:46 localhost NetworkManager[298]: <info>  [1576359106.2606] device 
(wlp18s0): state change: activated -> need-auth (reason 
'supplicant-disconnect', sys-iface-state: 'managed')
Dec 14 16:31:46 localhost NetworkManager[298]: <info>  [1576359106.2932] dhcp4 
(wlp18s0): canceled DHCP transaction, DHCP client pid 10342
Dec 14 16:31:46 localhost NetworkManager[298]: <info>  [1576359106.2932] dhcp4 
(wlp18s0): state changed bound -> done
Dec 14 16:31:46 localhost NetworkManager[298]: <info>  [1576359106.2952] dhcp6 
(wlp18s0): canceled DHCP transaction, DHCP client pid 10355
Dec 14 16:31:46 localhost NetworkManager[298]: <info>  [1576359106.2954] dhcp6 
(wlp18s0): state changed bound -> done
Dec 14 16:31:46 localhost NetworkManager[298]: <info>  [1576359106.2968] 
manager: NetworkManager state is now CONNECTING
Dec 14 16:31:46 localhost NetworkManager[298]: <warn>  [1576359106.3021] device 
(wlp18s0): No agents were available for this request.
Dec 14 16:31:46 localhost NetworkManager[298]: <info>  [1576359106.3023] device 
(wlp18s0): state change: need-auth -> failed (reason 'no-secrets', 
sys-iface-state: 'managed')
Dec 14 16:31:46 localhost NetworkManager[298]: <info>  [1576359106.3033] 
manager: NetworkManager state is now DISCONNECTED
Dec 14 16:31:46 localhost NetworkManager[298]: <warn>  [1576359106.3042] device 
(wlp18s0): Activation: failed for connection 'MY-AP-NAME'
Dec 14 16:31:46 localhost NetworkManager[298]: <info>  [1576359106.3048] device 
(wlp18s0): state change: failed -> disconnected (reason 'none', 
sys-iface-state: 'managed')
Dec 14 16:31:46 localhost avahi-daemon[306]: Withdrawing address record for 
fdb5:f1eb:7663::2a3 on wlp18s0.
Dec 14 16:31:46 localhost avahi-daemon[306]: Withdrawing address record for 
fdb5:f1eb:7663:0:3f6a:8955:6109:580 on wlp18s0.
Dec 14 16:31:46 localhost avahi-daemon[306]: Leaving mDNS multicast group on 
interface wlp18s0.IPv6 with address fdb5:f1eb:7663:0:3f6a:8955:6109:580.
Dec 14 16:31:46 localhost avahi-daemon[306]: Joining mDNS multicast group on 
interface wlp18s0.IPv6 with address fe80::105:d3cb:cb27:ba08.
Dec 14 16:31:46 localhost avahi-daemon[306]: Registering new address record for 
fe80::105:d3cb:cb27:ba08 on wlp18s0.*.
Dec 14 16:31:46 localhost avahi-daemon[306]: Withdrawing address record for 
fe80::105:d3cb:cb27:ba08 on wlp18s0.
Dec 14 16:31:46 localhost avahi-daemon[306]: Leaving mDNS multicast group on 
interface wlp18s0.IPv6 with address fe80::105:d3cb:cb27:ba08.
Dec 14 16:31:46 localhost avahi-daemon[306]: Interface wlp18s0.IPv6 no longer 
relevant for mDNS.
Dec 14 16:31:46 localhost avahi-daemon[306]: Withdrawing address record for 
192.168.10.159 on wlp18s0.
Dec 14 16:31:46 localhost avahi-daemon[306]: Leaving mDNS multicast group on 
interface wlp18s0.IPv4 with address 192.168.10.159.
Dec 14 16:31:46 localhost avahi-daemon[306]: Interface wlp18s0.IPv4 no longer 
relevant for mDNS.
Dec 14 16:31:46 localhost NetworkManager[298]: <info>  [1576359106.3211] device 
(wlp18s0): set-hw-addr: set MAC address to 5E:13:04:81:23:C6 (scanning)
Dec 14 16:31:46 localhost nscd: 264 monitored file `/etc/resolv.conf` was moved 
into place, adding watch
Dec 14 16:31:46 localhost nscd: 264 monitored file `/etc/resolv.conf` was moved 
into place, adding watch
Dec 14 16:31:46 localhost NetworkManager[298]: <info>  [1576359106.3474] device 
(wlp18s0): supplicant interface state: disconnected -> disabled
Dec 14 16:31:46 localhost NetworkManager[298]: <info>  [1576359106.3754] device 
(wlp18s0): supplicant interface state: disabled -> inactive
Dec 14 16:31:46 localhost wpa_supplicant[297]: wlp18s0: Reject scan trigger 
since one is already pending
Dec 14 16:37:27 localhost NetworkManager[298]: <info>  [1576359447.2136] device 
(wlp18s0): set-hw-addr: set MAC address to 02:EF:36:24:62:CE (scanning)
Dec 14 16:37:27 localhost NetworkManager[298]: <info>  [1576359447.2331] device 
(wlp18s0): supplicant interface state: inactive -> disabled
Dec 14 16:37:27 localhost NetworkManager[298]: <info>  [1576359447.2351] device 
(wlp18s0): supplicant interface state: disabled -> inactive
Dec 14 16:37:27 localhost wpa_supplicant[297]: wlp18s0: Reject scan trigger 
since one is already pending
Dec 14 16:42:42 localhost NetworkManager[298]: <info>  [1576359762.1565] device 
(wlp18s0): set-hw-addr: set MAC address to CE:98:BC:D0:F1:B9 (scanning)
Dec 14 16:42:42 localhost NetworkManager[298]: <info>  [1576359762.1758] device 
(wlp18s0): supplicant interface state: inactive -> disabled
Dec 14 16:42:42 localhost NetworkManager[298]: <info>  [1576359762.1996] device 
(wlp18s0): supplicant interface state: disabled -> inactive
[...]
--8<---------------cut here---------------end--------------->8---

The workaround is to reconnect manually with for example using

--8<---------------cut here---------------start------------->8---
nmcli con up ACESS-POINT-NAME
--8<---------------cut here---------------end--------------->8---

Which gives the following messages:

--8<---------------cut here---------------start------------->8---
Dec 18 22:00:48 localhost NetworkManager[298]: <info>  [1576724448.4205] 
agent-manager: req[0x2173a70, :1.46/nmcli-connect/1000]: agent registered
Dec 18 22:00:48 localhost NetworkManager[298]: <info>  [1576724448.4208] 
policy: auto-activating connection 'MY-AP-NAME' 
(172b7c50-4a3b-4b24-9d74-2e567aed460a)
Dec 18 22:00:48 localhost NetworkManager[298]: <info>  [1576724448.4223] device 
(wlp18s0): Activation: starting connection 'MY-AP-NAME' 
(172b7c50-4a3b-4b24-9d74-2e567aed460a)
Dec 18 22:00:48 localhost NetworkManager[298]: <info>  [1576724448.4226] device 
(wlp18s0): state change: disconnected -> prepare (reason 'none', 
sys-iface-state: 'managed')
Dec 18 22:00:48 localhost NetworkManager[298]: <info>  [1576724448.4233] 
manager: NetworkManager state is now CONNECTING
Dec 18 22:00:48 localhost NetworkManager[298]: <info>  [1576724448.4385] device 
(wlp18s0): set-hw-addr: reset MAC address to C0:F8:DA:5D:2F:2F (preserve)
Dec 18 22:00:48 localhost NetworkManager[298]: <info>  [1576724448.4653] device 
(wlp18s0): supplicant interface state: inactive -> disabled
Dec 18 22:00:48 localhost NetworkManager[298]: <info>  [1576724448.4656] device 
(wlp18s0): state change: prepare -> deactivating (reason 'new-activation', 
sys-iface-state: 'managed')
Dec 18 22:00:48 localhost NetworkManager[298]: <info>  [1576724448.4666] 
manager: NetworkManager state is now DISCONNECTING
Dec 18 22:00:48 localhost NetworkManager[298]: <info>  [1576724448.4674] device 
(wlp18s0): disconnecting for new activation request.
Dec 18 22:00:48 localhost NetworkManager[298]: <info>  [1576724448.4675] audit: 
op="connection-activate" uuid="172b7c50-4a3b-4b24-9d74-2e567aed460a" 
name="MY-AP-NAME" pid=6513 uid=1000 result="success"
Dec 18 22:00:48 localhost NetworkManager[298]: <info>  [1576724448.4677] device 
(wlp18s0): state change: deactivating -> disconnected (reason 'new-activation', 
sys-iface-state: 'managed')
Dec 18 22:00:48 localhost NetworkManager[298]: <info>  [1576724448.4842] device 
(wlp18s0): set-hw-addr: set MAC address to C2:40:8A:91:21:5F (scanning)
Dec 18 22:00:48 localhost NetworkManager[298]: <info>  [1576724448.5023] 
manager: NetworkManager state is now DISCONNECTED
Dec 18 22:00:48 localhost NetworkManager[298]: <info>  [1576724448.5032] device 
(wlp18s0): Activation: starting connection 'MY-AP-NAME' 
(172b7c50-4a3b-4b24-9d74-2e567aed460a)
Dec 18 22:00:48 localhost NetworkManager[298]: <info>  [1576724448.5053] device 
(wlp18s0): state change: disconnected -> prepare (reason 'none', 
sys-iface-state: 'managed')
Dec 18 22:00:48 localhost NetworkManager[298]: <info>  [1576724448.5067] 
manager: NetworkManager state is now CONNECTING
Dec 18 22:00:48 localhost NetworkManager[298]: <info>  [1576724448.5348] device 
(wlp18s0): set-hw-addr: reset MAC address to C0:F8:DA:5D:2F:2F (preserve)
Dec 18 22:00:48 localhost NetworkManager[298]: <info>  [1576724448.5511] device 
(wlp18s0): supplicant interface state: disabled -> inactive
Dec 18 22:00:48 localhost NetworkManager[298]: <info>  [1576724448.5517] device 
(wlp18s0): supplicant interface state: inactive -> disabled
Dec 18 22:00:48 localhost NetworkManager[298]: <info>  [1576724448.5519] device 
(wlp18s0): state change: prepare -> config (reason 'none', sys-iface-state: 
'managed')
Dec 18 22:00:48 localhost NetworkManager[298]: <info>  [1576724448.5526] device 
(wlp18s0): Activation: (wifi) access point 'MY-AP-NAME' has security, but 
secrets are required.
Dec 18 22:00:48 localhost NetworkManager[298]: <info>  [1576724448.5528] device 
(wlp18s0): state change: config -> need-auth (reason 'none', sys-iface-state: 
'managed')
Dec 18 22:00:48 localhost NetworkManager[298]: <info>  [1576724448.5585] device 
(wlp18s0): state change: need-auth -> prepare (reason 'none', sys-iface-state: 
'managed')
Dec 18 22:00:48 localhost NetworkManager[298]: <info>  [1576724448.5594] device 
(wlp18s0): state change: prepare -> config (reason 'none', sys-iface-state: 
'managed')
Dec 18 22:00:48 localhost NetworkManager[298]: <info>  [1576724448.5601] device 
(wlp18s0): Activation: (wifi) connection 'MY-AP-NAME' has security, and secrets 
exist.  No new secrets needed.
Dec 18 22:00:48 localhost NetworkManager[298]: <info>  [1576724448.5603] 
Config: added 'ssid' value 'MY-AP-NAME'
Dec 18 22:00:48 localhost NetworkManager[298]: <info>  [1576724448.5604] 
Config: added 'scan_ssid' value '1'
Dec 18 22:00:48 localhost NetworkManager[298]: <info>  [1576724448.5605] 
Config: added 'bgscan' value 'simple:30:-80:86400'
Dec 18 22:00:48 localhost NetworkManager[298]: <info>  [1576724448.5607] 
Config: added 'key_mgmt' value 'WPA-PSK WPA-PSK-SHA256'
Dec 18 22:00:48 localhost NetworkManager[298]: <info>  [1576724448.5608] 
Config: added 'psk' value '<hidden>'
Dec 18 22:00:48 localhost NetworkManager[298]: <info>  [1576724448.5609] 
Config: added 'ieee80211w' value '1'
Dec 18 22:00:48 localhost NetworkManager[298]: <info>  [1576724448.5913] device 
(wlp18s0): supplicant interface state: disabled -> inactive
Dec 18 22:00:48 localhost NetworkManager[298]: <info>  [1576724448.6136] device 
(wlp18s0): supplicant interface state: inactive -> scanning
Dec 18 22:00:49 localhost vmunix: [2882214.304001] wlp18s0: authenticate with 
20:4e:7f:85:ab:13
Dec 18 22:00:49 localhost wpa_supplicant[297]: wlp18s0: SME: Trying to 
authenticate with 20:4e:7f:85:ab:13 (SSID='MY-AP-NAME' freq=2422 MHz)
Dec 18 22:00:49 localhost vmunix: [2882214.322552] wlp18s0: send auth to 
20:4e:7f:85:ab:13 (try 1/3)
Dec 18 22:00:49 localhost vmunix: [2882214.325084] wlp18s0: authenticated
Dec 18 22:00:49 localhost NetworkManager[298]: <info>  [1576724449.6772] device 
(wlp18s0): supplicant interface state: scanning -> authenticating
Dec 18 22:00:49 localhost wpa_supplicant[297]: wlp18s0: Trying to associate 
with 20:4e:7f:85:ab:13 (SSID='MY-AP-NAME' freq=2422 MHz)
Dec 18 22:00:49 localhost vmunix: [2882214.329953] wlp18s0: associate with 
20:4e:7f:85:ab:13 (try 1/3)
Dec 18 22:00:49 localhost vmunix: [2882214.335176] wlp18s0: RX AssocResp from 
20:4e:7f:85:ab:13 (capab=0x431 status=0 aid=2)
Dec 18 22:00:49 localhost vmunix: [2882214.335346] wlp18s0: associated
Dec 18 22:00:49 localhost wpa_supplicant[297]: wlp18s0: Associated with 
20:4e:7f:85:ab:13
Dec 18 22:00:49 localhost wpa_supplicant[297]: wlp18s0: 
CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Dec 18 22:00:49 localhost NetworkManager[298]: <info>  [1576724449.6903] device 
(wlp18s0): supplicant interface state: authenticating -> associating
Dec 18 22:00:49 localhost NetworkManager[298]: <info>  [1576724449.6959] device 
(wlp18s0): supplicant interface state: associating -> associated
Dec 18 22:00:49 localhost wpa_supplicant[297]: wlp18s0: WPA: Key negotiation 
completed with 20:4e:7f:85:ab:13 [PTK=CCMP GTK=CCMP]
Dec 18 22:00:49 localhost vmunix: [2882214.348804] IPv6: 
ADDRCONF(NETDEV_CHANGE): wlp18s0: link becomes ready
Dec 18 22:00:49 localhost wpa_supplicant[297]: wlp18s0: CTRL-EVENT-CONNECTED - 
Connection to 20:4e:7f:85:ab:13 completed [id=0 id_str=]
Dec 18 22:00:49 localhost NetworkManager[298]: <info>  [1576724449.7044] device 
(wlp18s0): supplicant interface state: associated -> 4-way handshake
Dec 18 22:00:49 localhost NetworkManager[298]: <info>  [1576724449.7095] device 
(wlp18s0): supplicant interface state: 4-way handshake -> completed
Dec 18 22:00:49 localhost NetworkManager[298]: <info>  [1576724449.7096] device 
(wlp18s0): Activation: (wifi) Stage 2 of 5 (Device Configure) successful. 
Connected to wireless network "MY-AP-NAME"
Dec 18 22:00:49 localhost NetworkManager[298]: <info>  [1576724449.7102] device 
(wlp18s0): state change: config -> ip-config (reason 'none', sys-iface-state: 
'managed')
Dec 18 22:00:49 localhost NetworkManager[298]: <info>  [1576724449.7110] dhcp4 
(wlp18s0): activation: beginning transaction (timeout in 45 seconds)
Dec 18 22:00:49 localhost NetworkManager[298]: <info>  [1576724449.7170] dhcp4 
(wlp18s0): dhclient started with pid 6519
Dec 18 22:00:49 localhost avahi-daemon[306]: Joining mDNS multicast group on 
interface wlp18s0.IPv6 with address fe80::105:d3cb:cb27:ba08.
Dec 18 22:00:49 localhost avahi-daemon[306]: New relevant interface 
wlp18s0.IPv6 for mDNS.
Dec 18 22:00:49 localhost avahi-daemon[306]: Registering new address record for 
fe80::105:d3cb:cb27:ba08 on wlp18s0.*.
Dec 18 22:00:49 localhost wpa_supplicant[297]: wlp18s0: 
CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=CA
Dec 18 22:00:49 localhost dhclient: DHCPREQUEST for 192.168.10.159 on wlp18s0 
to 255.255.255.255 port 67
Dec 18 22:00:49 localhost dhclient: DHCPACK of 192.168.10.159 from 192.168.10.1
Dec 18 22:00:49 localhost NetworkManager[298]: <info>  [1576724449.7801] dhcp4 
(wlp18s0):   address 192.168.10.159
Dec 18 22:00:49 localhost NetworkManager[298]: <info>  [1576724449.7801] dhcp4 
(wlp18s0):   plen 24 (255.255.255.0)
Dec 18 22:00:49 localhost NetworkManager[298]: <info>  [1576724449.7801] dhcp4 
(wlp18s0):   gateway 192.168.10.1
Dec 18 22:00:49 localhost NetworkManager[298]: <info>  [1576724449.7802] dhcp4 
(wlp18s0):   lease time 4294967295
Dec 18 22:00:49 localhost NetworkManager[298]: <info>  [1576724449.7802] dhcp4 
(wlp18s0):   hostname 'apteryx'
Dec 18 22:00:49 localhost NetworkManager[298]: <info>  [1576724449.7802] dhcp4 
(wlp18s0):   nameserver '192.168.10.1'
Dec 18 22:00:49 localhost NetworkManager[298]: <info>  [1576724449.7802] dhcp4 
(wlp18s0):   domain name 'lan'
Dec 18 22:00:49 localhost NetworkManager[298]: <info>  [1576724449.7803] dhcp4 
(wlp18s0): state changed unknown -> bound
Dec 18 22:00:49 localhost avahi-daemon[306]: Joining mDNS multicast group on 
interface wlp18s0.IPv4 with address 192.168.10.159.
Dec 18 22:00:49 localhost avahi-daemon[306]: New relevant interface 
wlp18s0.IPv4 for mDNS.
Dec 18 22:00:49 localhost avahi-daemon[306]: Registering new address record for 
192.168.10.159 on wlp18s0.IPv4.
Dec 18 22:00:49 localhost NetworkManager[298]: <info>  [1576724449.7857] device 
(wlp18s0): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 
'managed')
Dec 18 22:00:49 localhost dhclient: Timeout too large reducing to: 2147483646 
(TIME_MAX - 1)
Dec 18 22:00:49 localhost dhclient: bound to 192.168.10.159 -- renewal in 
2147483648 seconds.
Dec 18 22:00:49 localhost NetworkManager[298]: <info>  [1576724449.7907] device 
(wlp18s0): state change: ip-check -> secondaries (reason 'none', 
sys-iface-state: 'managed')
Dec 18 22:00:49 localhost NetworkManager[298]: <info>  [1576724449.7915] device 
(wlp18s0): state change: secondaries -> activated (reason 'none', 
sys-iface-state: 'managed')
Dec 18 22:00:49 localhost NetworkManager[298]: <info>  [1576724449.7973] 
manager: NetworkManager state is now CONNECTED_LOCAL
Dec 18 22:00:49 localhost NetworkManager[298]: <info>  [1576724449.8058] 
manager: NetworkManager state is now CONNECTED_SITE
Dec 18 22:00:49 localhost NetworkManager[298]: <info>  [1576724449.8066] 
policy: set 'MY-AP-NAME' (wlp18s0) as default for IPv4 routing and DNS
Dec 18 22:00:49 localhost nscd: 264 monitored file `/etc/resolv.conf` was moved 
into place, adding watch
Dec 18 22:00:49 localhost NetworkManager[298]: <info>  [1576724449.8103] device 
(wlp18s0): Activation: successful, device activated.
Dec 18 22:00:49 localhost NetworkManager[298]: <info>  [1576724449.8116] 
manager: NetworkManager state is now CONNECTED_GLOBAL
Dec 18 22:00:50 localhost wpa_supplicant[297]: wlp18s0: 
CTRL-EVENT-SIGNAL-CHANGE above=1 signal=-74 noise=-91 txrate=19500
--8<---------------cut here---------------end--------------->8---

Maxim
[Prev in Thread]
Current Thread
[Next in Thread]
bug#38667: Network-Manager (sometimes) fails reconnecting to network automatically, Maxim Cournoyer <=
Prev by Date: bug#38666: Maybe netcat should support ipv6 ("-6" option)
Next by Date: bug#38628: [PATCH] gexp: Allow character literals in GEXP->SEXP.
Previous by thread: bug#38666: Maybe netcat should support ipv6 ("-6" option)
Next by thread: bug#38054: [bug#38395] Acknowledgement ([PATCH] gnu: mumble: Update to 1.3.0.)
Index(es):
- Date
- Thread