From debbugs-submit-bounces@debbugs.gnu.org Wed Dec 18 23:24:06 2019 Received: (at submit) by debbugs.gnu.org; 19 Dec 2019 04:24:06 +0000 Received: from localhost ([127.0.0.1]:44186 helo=debbugs.gnu.org) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1ihnM5-0006oT-Am for submit@debbugs.gnu.org; Wed, 18 Dec 2019 23:24:06 -0500 Received: from lists.gnu.org ([209.51.188.17]:60263) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1ihnM3-0006oL-AO for submit@debbugs.gnu.org; Wed, 18 Dec 2019 23:24:04 -0500 Received: from eggs.gnu.org ([2001:470:142:3::10]:33327) by lists.gnu.org with esmtp (Exim 4.90_1) (envelope-from ) id 1ihnLz-0000OC-DT for bug-guix@gnu.org; Wed, 18 Dec 2019 23:24:03 -0500 X-Spam-Checker-Version: SpamAssassin 3.3.2 (2011-06-06) on eggs.gnu.org X-Spam-Level: X-Spam-Status: No, score=0.8 required=5.0 tests=BAYES_50,FREEMAIL_FROM autolearn=disabled version=3.3.2 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1ihnLv-0008UO-QD for bug-guix@gnu.org; Wed, 18 Dec 2019 23:23:59 -0500 Received: from mail-qk1-x736.google.com ([2607:f8b0:4864:20::736]:43120) by eggs.gnu.org with esmtps (TLS1.0:RSA_AES_128_CBC_SHA1:16) (Exim 4.71) (envelope-from ) id 1ihnLv-0008RK-Kw for bug-guix@gnu.org; Wed, 18 Dec 2019 23:23:55 -0500 Received: by mail-qk1-x736.google.com with SMTP id t129so3556869qke.10 for ; Wed, 18 Dec 2019 20:23:55 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=from:to:subject:date:message-id:mime-version; bh=YD011vK6FUzfEogyJiT6SBbrL7SQ9bm4VzPmpPufddo=; b=AifI39MjxaXSHmIiqR2ixV2xQVrDMqKvwt+Q+F1/NbsfBomHfsXNtjTGD7yX2aRXP5 pGT4ATi3bbknyYNN2J8+KGiJ6LMpfiFNX3SWQ1J3+mfg0DHHCNWv6WJRy7O3Tq/VNkYT 3QqOP2uS3cn1fexTjGE5kuE36WBfEzloDOjt95uOrX4fsrbOWZ+8mmE5vQiGAV4sUrSV kiDTbpseORuAwk4OIVDxpkcdIq4mzg+y5ZHSL2Y3MBK8F6fM/OF6zDXb7yw7v7feZloN 7eSCp+bqCX0aNfYB3P4luKw3ndMM0Tyr7Xdmh9t/PLYDDLTT9ePHiNzjrgtMv649EOUI m3nQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:subject:date:message-id:mime-version; bh=YD011vK6FUzfEogyJiT6SBbrL7SQ9bm4VzPmpPufddo=; b=h6dNE5ODstEjUOIvtiqyROo63Zu3e2Ps3UvwZ5wR+SaZ+JOu2mPhTJePRRVgmpikPQ ujXa4yNAwuZx2TdW48f91db1VEyopedGF7soIuHIGi4mQGAa1sEYRbvdRa/cDfbmmIex 6UeMx6vgEZkyBAKig8QTHOdgA1Vvtlx+om9wDSI+0uxMiYzbwpD0c/y2fbo2GkeWuVli jW4ZXqE8w7UhrWmZm9cU20B9bwoVcx7+g7McoAa5ZNB0wUPipyH4fCNfUOtaSQsYjwhg 6QDAXLpObi8H29kKlczX25k6KVBDAQoW90zpHnc3RhvA1+ZWLmn9jZonz2NZ4zGwCVxH AEAQ== X-Gm-Message-State: APjAAAUBqRbRt8UgAUS66lWP1ZZBW+m1k5KLEyM9xmVAR7eoOpi9CJzm mebDmtq8iA5sopEcU0WMoolbMQeo X-Google-Smtp-Source: APXvYqxxarjHRjn0s6t9/Pg7Th59487vgBCn+kkm6lCZ0UbH3dRqGb44Emg1IO6z3vdWGzaIBtcv7A== X-Received: by 2002:a05:620a:84a:: with SMTP id u10mr6146588qku.182.1576729433359; Wed, 18 Dec 2019 20:23:53 -0800 (PST) Received: from apteryx (dsl-141-4.b2b2c.ca. [66.158.141.4]) by smtp.gmail.com with ESMTPSA id j194sm1385521qke.83.2019.12.18.20.23.52 for (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Wed, 18 Dec 2019 20:23:52 -0800 (PST) From: Maxim Cournoyer To: bug-guix Subject: Network-Manager (sometimes) fails reconnecting to network automatically Date: Wed, 18 Dec 2019 23:23:51 -0500 Message-ID: <87h81xeyeg.fsf@gmail.com> MIME-Version: 1.0 Content-Type: text/plain X-detected-operating-system: by eggs.gnu.org: Genre and OS details not recognized. X-Received-From: 2607:f8b0:4864:20::736 X-Spam-Score: 0.7 (/) X-Debbugs-Envelope-To: submit X-BeenThere: debbugs-submit@debbugs.gnu.org X-Mailman-Version: 2.1.18 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: debbugs-submit-bounces@debbugs.gnu.org Sender: "Debbugs-submit" X-Spam-Score: -2.3 (--) 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]: [1576353700.9145] sup-iface[0x20f30d0,wlp18s0]: connection disconnected (reason 2) Dec 14 15:01:40 localhost NetworkManager[298]: [1576353700.9199] device (wlp18s0): supplicant interface state: completed -> disconnected Dec 14 15:01:41 localhost NetworkManager[298]: [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]: [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]: [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]: [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 -> Dec 14 15:01:43 localhost ntpd[299]: 54.39.13.155 local addr 192.168.10.159 -> Dec 14 15:01:43 localhost ntpd[299]: 149.56.121.16 local addr 192.168.10.159 -> Dec 14 15:01:43 localhost ntpd[299]: 149.56.27.12 local addr 192.168.10.159 -> Dec 14 15:01:43 localhost ntpd[299]: 192.99.2.8 local addr 192.168.10.159 -> Dec 14 15:01:43 localhost ntpd[299]: 54.39.23.64 local addr 192.168.10.159 -> Dec 14 15:01:43 localhost ntpd[299]: 50.101.251.61 local addr 192.168.10.159 -> Dec 14 15:01:43 localhost ntpd[299]: 162.159.200.1 local addr 192.168.10.159 -> Dec 14 15:01:43 localhost ntpd[299]: 172.105.3.89 local addr 192.168.10.159 -> 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]: [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]: [1576358600.9195] dhcp6 (wlp18s0): valid_lft 4294967295 Dec 14 16:23:20 localhost NetworkManager[298]: [1576358600.9196] dhcp6 (wlp18s0): preferred_lft 4294967295 Dec 14 16:23:20 localhost NetworkManager[298]: [1576358600.9196] dhcp6 (wlp18s0): address fdb5:f1eb:7663::2a3 Dec 14 16:23:20 localhost NetworkManager[298]: [1576358600.9196] dhcp6 (wlp18s0): nameserver 'fdb5:f1eb:7663::1' Dec 14 16:23:20 localhost NetworkManager[298]: [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]: [1576359100.9141] sup-iface[0x20f30d0,wlp18s0]: connection disconnected (reason 2) Dec 14 16:31:40 localhost NetworkManager[298]: [1576359100.9198] device (wlp18s0): supplicant interface state: completed -> disconnected Dec 14 16:31:41 localhost NetworkManager[298]: [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]: [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]: [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]: [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 -> Dec 14 16:31:43 localhost ntpd[299]: 54.39.13.155 local addr 192.168.10.159 -> Dec 14 16:31:43 localhost ntpd[299]: 149.56.121.16 local addr 192.168.10.159 -> Dec 14 16:31:43 localhost ntpd[299]: 149.56.27.12 local addr 192.168.10.159 -> Dec 14 16:31:43 localhost ntpd[299]: 192.99.2.8 local addr 192.168.10.159 -> Dec 14 16:31:43 localhost ntpd[299]: 54.39.23.64 local addr 192.168.10.159 -> Dec 14 16:31:43 localhost ntpd[299]: 50.101.251.61 local addr 192.168.10.159 -> Dec 14 16:31:43 localhost ntpd[299]: 162.159.200.1 local addr 192.168.10.159 -> Dec 14 16:31:43 localhost ntpd[299]: 172.105.3.89 local addr 192.168.10.159 -> 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]: [1576359106.2542] sup-iface[0x20f30d0,wlp18s0]: connection disconnected (reason 2) Dec 14 16:31:46 localhost NetworkManager[298]: [1576359106.2594] device (wlp18s0): supplicant interface state: 4-way handshake -> disconnected Dec 14 16:31:46 localhost NetworkManager[298]: [1576359106.2604] device (wlp18s0): Activation: (wifi) disconnected during association, asking for new key Dec 14 16:31:46 localhost NetworkManager[298]: [1576359106.2606] device (wlp18s0): state change: activated -> need-auth (reason 'supplicant-disconnect', sys-iface-state: 'managed') Dec 14 16:31:46 localhost NetworkManager[298]: [1576359106.2932] dhcp4 (wlp18s0): canceled DHCP transaction, DHCP client pid 10342 Dec 14 16:31:46 localhost NetworkManager[298]: [1576359106.2932] dhcp4 (wlp18s0): state changed bound -> done Dec 14 16:31:46 localhost NetworkManager[298]: [1576359106.2952] dhcp6 (wlp18s0): canceled DHCP transaction, DHCP client pid 10355 Dec 14 16:31:46 localhost NetworkManager[298]: [1576359106.2954] dhcp6 (wlp18s0): state changed bound -> done Dec 14 16:31:46 localhost NetworkManager[298]: [1576359106.2968] manager: NetworkManager state is now CONNECTING Dec 14 16:31:46 localhost NetworkManager[298]: [1576359106.3021] device (wlp18s0): No agents were available for this request. Dec 14 16:31:46 localhost NetworkManager[298]: [1576359106.3023] device (wlp18s0): state change: need-auth -> failed (reason 'no-secrets', sys-iface-state: 'managed') Dec 14 16:31:46 localhost NetworkManager[298]: [1576359106.3033] manager: NetworkManager state is now DISCONNECTED Dec 14 16:31:46 localhost NetworkManager[298]: [1576359106.3042] device (wlp18s0): Activation: failed for connection 'MY-AP-NAME' Dec 14 16:31:46 localhost NetworkManager[298]: [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]: [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]: [1576359106.3474] device (wlp18s0): supplicant interface state: disconnected -> disabled Dec 14 16:31:46 localhost NetworkManager[298]: [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]: [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]: [1576359447.2331] device (wlp18s0): supplicant interface state: inactive -> disabled Dec 14 16:37:27 localhost NetworkManager[298]: [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]: [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]: [1576359762.1758] device (wlp18s0): supplicant interface state: inactive -> disabled Dec 14 16:42:42 localhost NetworkManager[298]: [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]: [1576724448.4205] agent-manager: req[0x2173a70, :1.46/nmcli-connect/1000]: agent registered Dec 18 22:00:48 localhost NetworkManager[298]: [1576724448.4208] policy: auto-activating connection 'MY-AP-NAME' (172b7c50-4a3b-4b24-9d74-2e567aed460a) Dec 18 22:00:48 localhost NetworkManager[298]: [1576724448.4223] device (wlp18s0): Activation: starting connection 'MY-AP-NAME' (172b7c50-4a3b-4b24-9d74-2e567aed460a) Dec 18 22:00:48 localhost NetworkManager[298]: [1576724448.4226] device (wlp18s0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed') Dec 18 22:00:48 localhost NetworkManager[298]: [1576724448.4233] manager: NetworkManager state is now CONNECTING Dec 18 22:00:48 localhost NetworkManager[298]: [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]: [1576724448.4653] device (wlp18s0): supplicant interface state: inactive -> disabled Dec 18 22:00:48 localhost NetworkManager[298]: [1576724448.4656] device (wlp18s0): state change: prepare -> deactivating (reason 'new-activation', sys-iface-state: 'managed') Dec 18 22:00:48 localhost NetworkManager[298]: [1576724448.4666] manager: NetworkManager state is now DISCONNECTING Dec 18 22:00:48 localhost NetworkManager[298]: [1576724448.4674] device (wlp18s0): disconnecting for new activation request. Dec 18 22:00:48 localhost NetworkManager[298]: [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]: [1576724448.4677] device (wlp18s0): state change: deactivating -> disconnected (reason 'new-activation', sys-iface-state: 'managed') Dec 18 22:00:48 localhost NetworkManager[298]: [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]: [1576724448.5023] manager: NetworkManager state is now DISCONNECTED Dec 18 22:00:48 localhost NetworkManager[298]: [1576724448.5032] device (wlp18s0): Activation: starting connection 'MY-AP-NAME' (172b7c50-4a3b-4b24-9d74-2e567aed460a) Dec 18 22:00:48 localhost NetworkManager[298]: [1576724448.5053] device (wlp18s0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed') Dec 18 22:00:48 localhost NetworkManager[298]: [1576724448.5067] manager: NetworkManager state is now CONNECTING Dec 18 22:00:48 localhost NetworkManager[298]: [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]: [1576724448.5511] device (wlp18s0): supplicant interface state: disabled -> inactive Dec 18 22:00:48 localhost NetworkManager[298]: [1576724448.5517] device (wlp18s0): supplicant interface state: inactive -> disabled Dec 18 22:00:48 localhost NetworkManager[298]: [1576724448.5519] device (wlp18s0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed') Dec 18 22:00:48 localhost NetworkManager[298]: [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]: [1576724448.5528] device (wlp18s0): state change: config -> need-auth (reason 'none', sys-iface-state: 'managed') Dec 18 22:00:48 localhost NetworkManager[298]: [1576724448.5585] device (wlp18s0): state change: need-auth -> prepare (reason 'none', sys-iface-state: 'managed') Dec 18 22:00:48 localhost NetworkManager[298]: [1576724448.5594] device (wlp18s0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed') Dec 18 22:00:48 localhost NetworkManager[298]: [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]: [1576724448.5603] Config: added 'ssid' value 'MY-AP-NAME' Dec 18 22:00:48 localhost NetworkManager[298]: [1576724448.5604] Config: added 'scan_ssid' value '1' Dec 18 22:00:48 localhost NetworkManager[298]: [1576724448.5605] Config: added 'bgscan' value 'simple:30:-80:86400' Dec 18 22:00:48 localhost NetworkManager[298]: [1576724448.5607] Config: added 'key_mgmt' value 'WPA-PSK WPA-PSK-SHA256' Dec 18 22:00:48 localhost NetworkManager[298]: [1576724448.5608] Config: added 'psk' value '' Dec 18 22:00:48 localhost NetworkManager[298]: [1576724448.5609] Config: added 'ieee80211w' value '1' Dec 18 22:00:48 localhost NetworkManager[298]: [1576724448.5913] device (wlp18s0): supplicant interface state: disabled -> inactive Dec 18 22:00:48 localhost NetworkManager[298]: [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]: [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]: [1576724449.6903] device (wlp18s0): supplicant interface state: authenticating -> associating Dec 18 22:00:49 localhost NetworkManager[298]: [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]: [1576724449.7044] device (wlp18s0): supplicant interface state: associated -> 4-way handshake Dec 18 22:00:49 localhost NetworkManager[298]: [1576724449.7095] device (wlp18s0): supplicant interface state: 4-way handshake -> completed Dec 18 22:00:49 localhost NetworkManager[298]: [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]: [1576724449.7102] device (wlp18s0): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed') Dec 18 22:00:49 localhost NetworkManager[298]: [1576724449.7110] dhcp4 (wlp18s0): activation: beginning transaction (timeout in 45 seconds) Dec 18 22:00:49 localhost NetworkManager[298]: [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]: [1576724449.7801] dhcp4 (wlp18s0): address 192.168.10.159 Dec 18 22:00:49 localhost NetworkManager[298]: [1576724449.7801] dhcp4 (wlp18s0): plen 24 (255.255.255.0) Dec 18 22:00:49 localhost NetworkManager[298]: [1576724449.7801] dhcp4 (wlp18s0): gateway 192.168.10.1 Dec 18 22:00:49 localhost NetworkManager[298]: [1576724449.7802] dhcp4 (wlp18s0): lease time 4294967295 Dec 18 22:00:49 localhost NetworkManager[298]: [1576724449.7802] dhcp4 (wlp18s0): hostname 'apteryx' Dec 18 22:00:49 localhost NetworkManager[298]: [1576724449.7802] dhcp4 (wlp18s0): nameserver '192.168.10.1' Dec 18 22:00:49 localhost NetworkManager[298]: [1576724449.7802] dhcp4 (wlp18s0): domain name 'lan' Dec 18 22:00:49 localhost NetworkManager[298]: [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]: [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]: [1576724449.7907] device (wlp18s0): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed') Dec 18 22:00:49 localhost NetworkManager[298]: [1576724449.7915] device (wlp18s0): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed') Dec 18 22:00:49 localhost NetworkManager[298]: [1576724449.7973] manager: NetworkManager state is now CONNECTED_LOCAL Dec 18 22:00:49 localhost NetworkManager[298]: [1576724449.8058] manager: NetworkManager state is now CONNECTED_SITE Dec 18 22:00:49 localhost NetworkManager[298]: [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]: [1576724449.8103] device (wlp18s0): Activation: successful, device activated. Dec 18 22:00:49 localhost NetworkManager[298]: [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 From debbugs-submit-bounces@debbugs.gnu.org Fri May 01 09:40:32 2020 Received: (at 38667-done) by debbugs.gnu.org; 1 May 2020 13:40:32 +0000 Received: from localhost ([127.0.0.1]:48456 helo=debbugs.gnu.org) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1jUVu4-0007Wh-Dp for submit@debbugs.gnu.org; Fri, 01 May 2020 09:40:32 -0400 Received: from mail-qt1-f175.google.com ([209.85.160.175]:46415) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1jUVu2-0007WR-RM for 38667-done@debbugs.gnu.org; Fri, 01 May 2020 09:40:31 -0400 Received: by mail-qt1-f175.google.com with SMTP id g26so4032928qtv.13 for <38667-done@debbugs.gnu.org>; Fri, 01 May 2020 06:40:30 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=from:to:cc:subject:references:date:in-reply-to:message-id :user-agent:mime-version; bh=F4DtlXNni8YwSXH16E4e0dfXfYfzC8167sY83PHoDrs=; b=ar3sQaitX5QTdvUU84H2Qo8YVz3hZHIi+pHtkuhe1JtdWoWbpPO7HFAqtku+vaNDxN nQY4H+/H/s2Bn9gyDI8suwiQ16oGLTx9RZY6x7+2R2/ZncqlwDfYvxZTIOEBZmrarEND 4s6o8lHsyck39q23ZP4nfTJKahzIZMnjm4b7ltcBVIUhhU99oCzsTBaPS+D4stS2buhw GI3aEMKzb/6J+bIRFIEAHvunM7FQio1tc2t6y7jEapv++8rcKxgXLJ0GeeQMjNY7R5ip YOLytsKKoUxG+DPh3f0cujRuPBc7I7x6f90XAn4v+S6OTG31+v5W8juQSA+sWGEKdSB5 FkbQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:references:date:in-reply-to :message-id:user-agent:mime-version; bh=F4DtlXNni8YwSXH16E4e0dfXfYfzC8167sY83PHoDrs=; b=tx/jXEzc8GZ40JXhWZVPOxS9F91iEncCeOfj3/pfTGM9e3MvPWSaqcIrB0YtgoTrX0 nPRd4bWMmj7uMcy0/F1Tts2gCfbl/gZG0XF+PZ2aHh34NjAtS46kd+9JZp216raHnO4Q c7FDkrL6KNUz//euWqlR3R2dGBKmdprpLOxre8zAzHbHRJh1c+66piLxYYdMpFcuAcM2 YJRhO97NyaeifKTEQ7od6SI1bW2acwD7J507muY6TWqRtnMTCAhGA7dJpQQ8lgm4zUeO WAdSjPazYt32jnwwMplVRGk/qvSwh1ay5UpTX1r5n13j5cB3YxDCVCMEqWzDTSZHOTdy FNoA== X-Gm-Message-State: AGi0PuYHYzE+N8AKvk/tn50xWZttjdBie6mLsvDQ17+5DClms1h45SUm OgFIESbBpxUfeLQCWxtM1vQkN2o4 X-Google-Smtp-Source: APiQypIfRm+E86zxPKuYFCiwFl2F4yPxAMzCi7zaxng5LjPR06Xk+mJu/OKgaN0KC4shuO89eaudlA== X-Received: by 2002:ac8:22ad:: with SMTP id f42mr3784460qta.292.1588340425081; Fri, 01 May 2020 06:40:25 -0700 (PDT) Received: from hurd (dsl-153-87.b2b2c.ca. [66.158.153.87]) by smtp.gmail.com with ESMTPSA id o43sm2568999qtf.46.2020.05.01.06.40.24 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Fri, 01 May 2020 06:40:24 -0700 (PDT) From: maxim.cournoyer@gmail.com X-Google-Original-From: maxim@hurd.i-did-not-set--mail-host-address--so-tickle-me To: Maxim Cournoyer Subject: Re: bug#38667: Network-Manager (sometimes) fails reconnecting to network automatically References: <87h81xeyeg.fsf@gmail.com> Date: Fri, 01 May 2020 09:40:19 -0400 In-Reply-To: <87h81xeyeg.fsf@gmail.com> (Maxim Cournoyer's message of "Wed, 18 Dec 2019 23:23:51 -0500") Message-ID: <87zharkc3g.fsf@hurd.i-did-not-set--mail-host-address--so-tickle-me> User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/26.3 (gnu/linux) MIME-Version: 1.0 Content-Type: text/plain X-Spam-Score: 0.0 (/) X-Debbugs-Envelope-To: 38667-done Cc: 38667-done@debbugs.gnu.org X-BeenThere: debbugs-submit@debbugs.gnu.org X-Mailman-Version: 2.1.18 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: debbugs-submit-bounces@debbugs.gnu.org Sender: "Debbugs-submit" X-Spam-Score: -1.0 (-) 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 From unknown Fri Jun 13 10:54:43 2025 Received: (at fakecontrol) by fakecontrolmessage; To: internal_control@debbugs.gnu.org From: Debbugs Internal Request Subject: Internal Control Message-Id: bug archived. Date: Sat, 30 May 2020 11:24:06 +0000 User-Agent: Fakemail v42.6.9 # This is a fake control message. # # The action: # bug archived. thanks # This fakemail brought to you by your local debbugs # administrator