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

From: [email-masked] (GNU bug Tracking System)
Date: Fri, 01 May 2020 13:41:01 +0000

Your bug report

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

which was filed against the guix package, has been closed.

The explanation is attached below, along with your original report.
If you require more details, please reply to [email-masked].

-- 
38667: http://debbugs.gnu.org/cgi/bugreport.cgi?bug=38667
GNU Bug Tracking System
Contact [email-masked] with problems

Subject: Re: bug#38667: Network-Manager (sometimes) fails reconnecting to network automatically
From: [email-masked]
To: Maxim Cournoyer <[email-masked]>
Cc: [email-masked]
Date: Fri, 01 May 2020 09:40:19 -0400
List-Id: <debbugs-submit.debbugs.gnu.org>

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

Subject: Network-Manager (sometimes) fails reconnecting to network automatically
From: Maxim Cournoyer <[email-masked]>
To: bug-guix <[email-masked]>
Date: Wed, 18 Dec 2019 23:23:51 -0500
List-Id: <debbugs-submit.debbugs.gnu.org>

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