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

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

[Maxim Cournoyer]

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

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

[maxim.cournoyer]

I haven't seen this problem in a long time, so I'm closing the issue.  I
suspect it is more a problem with Network Manager than with Guix.

Maxim