Re: Recent iwlwifi failures on AX200

In reply to: Bjoern A. Zeeb: "Re: Recent iwlwifi failures on AX200"
Go to: [ bottom of page ] [ top of archives ] [ this month ]
From: Kevin Oberman <rkoberman_at_gmail.com>
Date: Fri, 29 Jul 2022 06:18:50 UTC
On Thu, Jul 28, 2022 at 11:17 AM Bjoern A. Zeeb <bz@freebsd.org> wrote:

> On Thu, 28 Jul 2022, Kevin Oberman wrote:
>
> > After a long interval of no iwlwifi problems, I have had two failures
> which
> > required a network restart.
> >
> > Running 13.1-STABLE #0 stable/13-n251476-141e9a5b3ebfrom June 21. (Time
> to
> > update).
> >
> > I see the following in my kernel log:
>
> What's before this?
>
> Why did the interface go to down?
>
> Did wpa_supplicant log anything?
>
> [...]
> --
> Bjoern A. Zeeb                                                     r15:7
>

Nothing until after the interface is down.

Sorry! I inadvertently filtered out way too many messages. Looks like wpa
issues may be at the center of this. Here is a complete log extract:
Jul 27 22:14:53 ptavv kernel: wlan0: link state changed to DOWN
Jul 27 22:14:53 ptavv wpa_supplicant[1202]: wlan0: CTRL-EVENT-DISCONNECTED
bssid=4c:ed:fb:37:b0:20 reason=0
Jul 27 22:14:53 ptavv wpa_supplicant[1202]: ioctl[SIOCS80211, op=20, val=0,
arg_len=7]: Can't assign requested address
Jul 27 22:15:55 ptavv wpa_supplicant[1202]: wlan0: Trying to associate with
4c:ed:fb:37:b0:24 (SSID='babcom 5' freq=5180 MHz)
Jul 27 22:15:55 ptavv wpa_supplicant[1202]: Failed to add supported
operating classes IE
Jul 27 22:15:55 ptavv kernel: wlan0: link state changed to UP
Jul 27 22:15:55 ptavv wpa_supplicant[1202]: wlan0: Associated with
4c:ed:fb:37:b0:24
Jul 27 22:15:55 ptavv wpa_supplicant[1202]: wlan0: WPA: Key negotiation
completed with 4c:ed:fb:37:b0:24 [PTK=CCMP GTK=CCMP]
Jul 27 22:15:55 ptavv wpa_supplicant[1202]: wlan0: CTRL-EVENT-CONNECTED -
Connection to 4c:ed:fb:37:b0:24 completed [id=2 id_str=]
Jul 27 22:15:55 ptavv dhclient[90645]: New IP Address (wlan0): 192.168.1.24
Jul 27 22:15:55 ptavv dhclient[90649]: New Subnet Mask (wlan0):
255.255.255.0
Jul 27 22:15:55 ptavv dhclient[90653]: New Broadcast Address (wlan0):
192.168.1.255
Jul 27 22:15:55 ptavv dhclient[90657]: New Routers (wlan0): 192.168.1.1
Jul 27 22:16:43 ptavv dhclient[1343]: My address (192.168.1.24) was
deleted, dhclient exiting
Jul 27 22:16:43 ptavv wpa_supplicant[1202]: wlan0: CTRL-EVENT-DISCONNECTED
bssid=4c:ed:fb:37:b0:24 reason=3 locally_generated=1
Jul 27 22:16:43 ptavv kernel: wlan0: link state changed to DOWN
Jul 27 22:16:43 ptavv dhclient[1343]: connection closed
Jul 27 22:16:43 ptavv dhclient[1343]: exiting.
Jul 27 22:16:43 ptavv wpa_supplicant[1202]: wlan0: CTRL-EVENT-TERMINATING
Jul 27 22:16:43 ptavv kernel: iwlwifi0: iwl_trans_send_cmd bad state = 0
Jul 27 22:16:43 ptavv kernel: iwlwifi0: Failed to remove MAC context: -5
Jul 27 22:16:43 ptavv kernel: iwlwifi0: iwl_trans_send_cmd bad state = 0
Jul 27 22:16:43 ptavv kernel: iwlwifi0: Failed to synchronize multicast
groups update
Jul 27 22:16:43 ptavv kernel: iwlwifi0: iwl_trans_send_cmd bad state = 0
Jul 27 22:16:43 ptavv kernel: iwlwifi0: Failed to synchronize multicast
groups update
Jul 27 22:16:43 ptavv kernel: iwlwifi0: iwl_trans_send_cmd bad state = 0
Jul 27 22:16:43 ptavv kernel: iwlwifi0: Failed to synchronize multicast
groups update
Jul 27 22:16:43 ptavv rtsold[1445]: <rtsock_input_ifannounce> interface
wlan0 removed
Jul 27 22:16:43 ptavv kernel: wlan0: Ethernet address: 6c:6a:77:ed:ce:d9
Jul 27 22:16:43 ptavv wpa_supplicant[90855]: Successfully initialized
wpa_supplicant
Jul 27 22:16:43 ptavv wpa_supplicant[90855]: ioctl[SIOCS80211, op=20,
val=0, arg_len=7]: Invalid argument
Jul 27 22:16:43 ptavv syslogd: last message repeated 1 times
Jul 27 22:16:45 ptavv wpa_supplicant[90856]: wlan0: Trying to associate
with 4c:ed:fb:37:b0:20 (SSID='babcom' freq=2437 MHz)
Jul 27 22:16:45 ptavv wpa_supplicant[90856]: Failed to add supported
operating classes IE
Jul 27 22:16:45 ptavv kernel: wlan0: link state changed to UP
Jul 27 22:16:45 ptavv wpa_supplicant[90856]: wlan0: Associated with
4c:ed:fb:37:b0:20
Jul 27 22:16:45 ptavv dhclient[90870]: send_packet: No buffer space
available
Jul 27 22:16:45 ptavv wpa_supplicant[90856]: wlan0: WPA: Key negotiation
completed with 4c:ed:fb:37:b0:20 [PTK=CCMP GTK=CCMP]
Jul 27 22:16:45 ptavv wpa_supplicant[90856]: wlan0: CTRL-EVENT-CONNECTED -
Connection to 4c:ed:fb:37:b0:20 completed [id=1 id_str=]
Jul 27 22:16:47 ptavv kernel: wlan0: link state changed to DOWN
Jul 27 22:16:47 ptavv wpa_supplicant[90856]: wlan0: CTRL-EVENT-DISCONNECTED
bssid=4c:ed:fb:37:b0:20 reason=0
Jul 27 22:16:47 ptavv wpa_supplicant[90856]: ioctl[SIOCS80211, op=20,
val=0, arg_len=7]: Can't assign requested address
Jul 27 22:16:48 ptavv wpa_supplicant[90856]: wlan0: Trying to associate
with 4c:ed:fb:37:b0:20 (SSID='babcom' freq=2437 MHz)
Jul 27 22:16:48 ptavv wpa_supplicant[90856]: Failed to add supported
operating classes IE
Jul 27 22:16:48 ptavv kernel: wlan0: link state changed to UP
Jul 27 22:16:48 ptavv wpa_supplicant[90856]: wlan0: Associated with
4c:ed:fb:37:b0:20
Jul 27 22:16:48 ptavv dhclient[90870]: send_packet: No buffer space
available
Jul 27 22:16:48 ptavv syslogd: last message repeated 1 times
Jul 27 22:16:48 ptavv wpa_supplicant[90856]: wlan0: WPA: Key negotiation
completed with 4c:ed:fb:37:b0:20 [PTK=CCMP GTK=CCMP]
Jul 27 22:16:48 ptavv wpa_supplicant[90856]: wlan0: CTRL-EVENT-CONNECTED -
Connection to 4c:ed:fb:37:b0:20 completed [id=1 id_str=]
Jul 27 22:16:51 ptavv dhclient[90928]: New IP Address (wlan0): 192.168.1.
-- 
Kevin Oberman, Part time kid herder and retired Network Engineer
E-mail: rkoberman@gmail.com
PGP Fingerprint: D03FB98AFA78E3B78C1694B318AB39EF1B055683