[Bug 281994] iwm: firmware crash

From: <bugzilla-noreply_at_freebsd.org>
Date: Sun, 22 Dec 2024 20:07:00 UTC
https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=281994

--- Comment #6 from Bill Blake <billblake2018@gmail.com> ---
(In reply to Bjoern A. Zeeb from comment #4)

Some points about my setup and an overview of what I did:

My laptop runs FreeBSD 14.1 and connects to the net via the hotspot on MyPhone,
an Android phone which normally uses the 5 GHz band for its hotspot. Generally
speaking, my laptop is always connected to MyPhone, except when I leave and
take MyPhone with me. When I return, it is not uncommon to have reconnection
difficulties. If I use MyPhone's wifi (thus switching off the hotspot) while
I'm out, it basically never reconnects; I have to restart the network. So my
general rule is, if I return and the connection doesn't come up after a minute
or two after I've turned my hotspot back on, I "wpa_cli reassoc" and/or just
restart my network and that usually fixes things.

I don't use the standard network scripts. "netop" is the script that devd calls
to handle network related events. One important aspect of my setup is that
wpa_supplicant is not called until *after* an "ifconfig wlan0 [list] scan"
returns one of the known networks. All of the iwm panics happen after a known
network has been seen and wpa_supplicant started.

I'll start with an iwm panic from two months ago. That panic looks closer to
yours than my recent ones do. However, after that panic, my laptop successfully
connected to MyPhone. Three days ago, I took MyPhone with me, and the reconnect
was normal. I didn't take MyPhone out again until yesterday.

When I returned yesterday, it didn't reconnect. After reboots and power cycles,
it still didn't connect. Mostly, there were iwm panics. There were a few other
oddities, which I'll detail.

Aside from the iwm panics, the most notable thing in the log of the recent
events is that wpa_supplicant reported the wrong band when it tried to
associate. When netop was called after wlan0 was created, it first looked for a
known AP and found MyPhone, then it started wpa_supplicant. Wpa_supplicant then
tried to associate with MyPhone on the 2.4 GHz band even though MyPhone was
using 5 GHz. Things only started working normally when I switched MyPhone to
2.4 GHz. And they continued working normally when I switched it back to 5 GHz.

Anyway, here's a more detailed analysis of what I found.

2024-10-18 using the generic kernel: For reasons I don't recall, I booted into
the generic kernel. MyPhone was found and an attempt was made to connect to it.
That timed out. There are messages from iwm after the timeout which appear to
be common to every connection failure. The netop lines beginning "count:" are
from checking the output of ifconfig wlan0 list scan, with a periodic ifconfig
wlan0 scan thrown in.

07:11:25.908224 devd 1441 - - Executing '/home/admin/libexec/netop $'IFNET'
$'wlan0' $'ATTACH' $'''
07:11:26.020727 netop 1584 - - call: IFNET wlan0 ATTACH
07:11:26.044030 netop 1584 - - run: daemon -cf /home/admin/libexec/netop daemon
wlan0 wpastart
07:11:26.048701 devd 1441 - - Processing event '!system=ETHERNET
subsystem=wlan0 type=IFATTACH'
07:11:26.075833 netop 1598 - - call: daemon wlan0 wpastart -
07:11:26.098293 netop 1598 - - run: ifconfig wlan0 up
07:11:26.333287 netop 1598 - - count: 0, networks:
07:11:27.408988 netop 1598 - - count: 0, networks:
07:11:28.438501 netop 1598 - - count: 1, networks: MyPhone, -50
07:11:28.440461 netop 1598 - - run: /usr/sbin/wpa_supplicant -d -d -s -B -i
wlan0 -c /home/admin/etc/wpa_supplicant.conf -D bsd -P
/var/run/wpa_supplicant/wlan0.pid
07:11:28.584498 wpa_supplicant 1633 - - Successfully initialized wpa_supplicant
07:11:28.652878 wpa_supplicant 1633 - - ioctl[SIOCS80211, op=20, val=0,
arg_len=7]: Invalid argument
07:11:28.652885 wpa_supplicant 1633 - - ioctl[SIOCS80211, op=20, val=0,
arg_len=7]: Invalid argument
07:11:30.259515 wpa_supplicant 1634 - - wlan0: Trying to associate with
da:28:8d:0f:bc:b5 (SSID='MyPhone' freq=5180 MHz)
07:11:40.319564 wpa_supplicant 1634 - - wlan0: Authentication with
da:28:8d:0f:bc:b5 timed out.
07:11:40.319771 kernel - - - iwm0: Failed to send binding (action:1): 35
07:11:40.319845 kernel - - - iwm0: iwm_auth: binding update cmd
07:11:40.319912 kernel - - - iwm0: iwm_newstate: could not move to auth state:
35
07:11:40.319759 wpa_supplicant 1634 - - wlan0: CTRL-EVENT-DISCONNECTED
bssid=da:28:8d:0f:bc:b5 reason=3 locally_generated=1
07:11:40.319827 wpa_supplicant 1634 - - BSSID da:28:8d:0f:bc:b5 ignore list
count incremented to 2, ignoring for 10 seconds
07:11:40.319987 wpa_supplicant 1634 - - wlan0: CTRL-EVENT-DSCP-POLICY clear_all

wpa_supplicant tried again and the controller panicked.

07:11:41.197630 wpa_supplicant 1634 - - wlan0: Trying to associate with
da:28:8d:0f:bc:b5 (SSID='MyPhone' freq=5180 MHz)
07:11:41.202101 kernel - - - iwm0: dumping device error log
07:11:41.202137 kernel - - - iwm0: Start Error Log Dump:
07:11:41.202160 kernel - - - iwm0: Status: 0x3, count: 6
07:11:41.202182 kernel - - - iwm0: 0x00003001 | ADVANCED_SYSASSERT
07:11:41.202206 kernel - - - iwm0: 000022F0 | trm_hw_status0
07:11:41.202230 kernel - - - iwm0: 00000000 | trm_hw_status1
07:11:41.202255 kernel - - - iwm0: 00456D06 | branchlink2
07:11:41.202285 kernel - - - iwm0: 0046064A | interruptlink1
07:11:41.202312 kernel - - - iwm0: 00000000 | interruptlink2
07:11:41.202341 kernel - - - iwm0: 00000001 | data1
07:11:41.202371 kernel - - - iwm0: 00000000 | data2
07:11:41.202402 kernel - - - iwm0: DEADBEEF | data3
07:11:41.202434 kernel - - - iwm0: 001FDB16 | beacon time
07:11:41.202468 kernel - - - iwm0: 00BB55C6 | tsf low
07:11:41.202502 kernel - - - iwm0: 00000000 | tsf hi
07:11:41.202538 kernel - - - iwm0: 00000000 | time gp1
07:11:41.202574 kernel - - - iwm0: 00BB55C8 | time gp2
07:11:41.202612 kernel - - - iwm0: 00000001 | uCode revision type
07:11:41.202651 kernel - - - iwm0: 00000022 | uCode version major
07:11:41.202691 kernel - - - iwm0: BA501B11 | uCode version minor
07:11:41.202733 kernel - - - iwm0: 00000312 | hw version
07:11:41.202775 kernel - - - iwm0: 0080FF0F | board version
07:11:41.202819 kernel - - - iwm0: 0929002B | hcmd
07:11:41.202864 kernel - - - iwm0: 00022080 | isr0
07:11:41.202910 kernel - - - iwm0: 00000000 | isr1
07:11:41.202957 kernel - - - iwm0: 08201802 | isr2
07:11:41.203006 kernel - - - iwm0: 00400080 | isr3
07:11:41.203055 kernel - - - iwm0: 00000000 | isr4
07:11:41.203105 kernel - - - iwm0: 09280008 | last cmd Id
07:11:41.203157 kernel - - - iwm0: 00000000 | wait_event
07:11:41.203209 kernel - - - iwm0: 00000000 | l2p_control
07:11:41.203263 kernel - - - iwm0: 00000000 | l2p_duration
07:11:41.203321 kernel - - - iwm0: 00000000 | l2p_mhvalid
07:11:41.203377 kernel - - - iwm0: 00000000 | l2p_addr_match
07:11:41.203434 kernel - - - iwm0: 0000008F | lmpm_pmg_sel
07:11:41.203492 kernel - - - iwm0: 28020233 | timestamp
07:11:41.203552 kernel - - - iwm0: 00003838 | flow_handler
07:11:41.203613 kernel - - - iwm0: Start UMAC Error Log Dump:
07:11:41.203675 kernel - - - iwm0: Status: 0x3, count: 7
07:11:41.203738 kernel - - - iwm0: 0x00000070 | ADVANCED_SYSASSERT
07:11:41.203803 kernel - - - iwm0: 0x00000000 | umac branchlink1
07:11:41.203869 kernel - - - iwm0: 0xC0087D08 | umac branchlink2
07:11:41.203936 kernel - - - iwm0: 0xC008F006 | umac interruptlink1
07:11:41.204004 kernel - - - iwm0: 0xC0083A08 | umac interruptlink2
07:11:41.204074 kernel - - - iwm0: 0x00000800 | umac data1
07:11:41.204145 kernel - - - iwm0: 0xC0083A08 | umac data2
07:11:41.204217 kernel - - - iwm0: 0xDEADBEEF | umac data3
07:11:41.204308 kernel - - - iwm0: 0x00000022 | umac major
07:11:41.204329 kernel - - - iwm0: 0xBA501B11 | umac minor
07:11:41.204350 kernel - - - iwm0: 0xC088628C | frame pointer
07:11:41.204372 kernel - - - iwm0: 0xC088628C | stack pointer
07:11:41.204395 kernel - - - iwm0: 0x0929002B | last host cmd
07:11:41.204419 kernel - - - iwm0: 0x00000000 | isr status reg
07:11:41.204444 kernel - - - iwm0: driver status:
07:11:41.204471 kernel - - - iwm0:   tx ring  0: qid=0  cur=0   queued=0
07:11:41.204499 kernel - - - iwm0:   tx ring  1: qid=1  cur=0   queued=0
07:11:41.204528 kernel - - - iwm0:   tx ring  2: qid=2  cur=0   queued=0
07:11:41.204559 kernel - - - iwm0:   tx ring  3: qid=3  cur=0   queued=0
07:11:41.204591 kernel - - - iwm0:   tx ring  4: qid=4  cur=0   queued=0
07:11:41.204625 kernel - - - iwm0:   tx ring  5: qid=5  cur=0   queued=0
07:11:41.204660 kernel - - - iwm0:   tx ring  6: qid=6  cur=0   queued=0
07:11:41.204699 kernel - - - iwm0:   tx ring  7: qid=7  cur=0   queued=0
07:11:41.204736 kernel - - - iwm0:   tx ring  8: qid=8  cur=0   queued=0
07:11:41.204776 kernel - - - iwm0:   tx ring  9: qid=9  cur=42  queued=1
07:11:41.204816 kernel - - - iwm0:   tx ring 10: qid=10 cur=0   queued=0
07:11:41.204858 kernel - - - iwm0:   tx ring 11: qid=11 cur=0   queued=0
07:11:41.204901 kernel - - - iwm0:   tx ring 12: qid=12 cur=0   queued=0
07:11:41.204946 kernel - - - iwm0:   tx ring 13: qid=13 cur=0   queued=0
07:11:41.204995 kernel - - - iwm0:   tx ring 14: qid=14 cur=0   queued=0
07:11:41.205042 kernel - - - iwm0:   tx ring 15: qid=15 cur=0   queued=0
07:11:41.205091 kernel - - - iwm0:   tx ring 16: qid=16 cur=0   queued=0
07:11:41.205141 kernel - - - iwm0:   tx ring 17: qid=17 cur=0   queued=0
07:11:41.205192 kernel - - - iwm0:   tx ring 18: qid=18 cur=0   queued=0
07:11:41.205245 kernel - - - iwm0:   tx ring 19: qid=19 cur=0   queued=0
07:11:41.205302 kernel - - - iwm0:   tx ring 20: qid=20 cur=0   queued=0
07:11:41.205358 kernel - - - iwm0:   tx ring 21: qid=21 cur=0   queued=0
07:11:41.205415 kernel - - - iwm0:   tx ring 22: qid=22 cur=0   queued=0
07:11:41.205473 kernel - - - iwm0:   tx ring 23: qid=23 cur=0   queued=0
07:11:41.205533 kernel - - - iwm0:   tx ring 24: qid=24 cur=0   queued=0
07:11:41.205594 kernel - - - iwm0:   tx ring 25: qid=25 cur=0   queued=0
07:11:41.205656 kernel - - - iwm0:   tx ring 26: qid=26 cur=0   queued=0
07:11:41.205720 kernel - - - iwm0:   tx ring 27: qid=27 cur=0   queued=0
07:11:41.205785 kernel - - - iwm0:   tx ring 28: qid=28 cur=0   queued=0
07:11:41.205852 kernel - - - iwm0:   tx ring 29: qid=29 cur=0   queued=0
07:11:41.205920 kernel - - - iwm0:   tx ring 30: qid=30 cur=0   queued=0
07:11:41.205990 kernel - - - iwm0:   rx ring: cur=62
07:11:41.206060 kernel - - - iwm0:   802.11 state 1
07:11:41.206132 kernel - - - iwm0: iwm_intr: controller panicked, iv_state = 1;
restarting
07:11:41.202092 wpa_supplicant 1634 - - wlan0: CTRL-EVENT-DISCONNECTED
bssid=da:28:8d:0f:bc:b5 reason=3 locally_generated=1
07:11:42.268272 kernel - - - iwm0: Failed to send binding (action:1): 35
07:11:42.268287 kernel - - - iwm0: iwm_auth: binding update cmd
07:11:42.268294 kernel - - - iwm0: iwm_newstate: could not move to auth state:
35

Third time was the charm; the connection worked.

07:11:43.771810 wpa_supplicant 1634 - - wlan0: Trying to associate with
da:28:8d:0f:bc:b5 (SSID='MyPhone' freq=5180 MHz)
07:11:43.823014 kernel - - - wlan0: link state changed to UP
07:11:43.822999 wpa_supplicant 1634 - - wlan0: Associated with
da:28:8d:0f:bc:b5
07:11:45.972310 wpa_supplicant 1634 - - wlan0: WPA: Key negotiation completed
with da:28:8d:0f:bc:b5 [PTK=CCMP GTK=CCMP]
07:11:45.972376 wpa_supplicant 1634 - - wlan0: CTRL-EVENT-CONNECTED -
Connection to da:28:8d:0f:bc:b5 completed [id=0 id_str=]

2024-12-19, using my custom kernel: I went out, taking MyPhone with me. The
reconnect was normal:

17:55:26.636988 wpa_supplicant 88544 - - wlan0: Trying to associate with
16:84:2d:61:a5:c0 (SSID='MyPhone' freq=5180 MHz)
17:55:26.649910 kernel - - - [2507467] wlan0: link state changed to UP
17:55:26.649913 wpa_supplicant 88544 - - wlan0: Associated with
16:84:2d:61:a5:c0
17:55:26.670894 wpa_supplicant 88544 - - wlan0: WPA: Key negotiation completed
with 16:84:2d:61:a5:c0 [PTK=CCMP GTK=CCMP]
17:55:26.670969 wpa_supplicant 88544 - - wlan0: CTRL-EVENT-CONNECTED -
Connection to 16:84:2d:61:a5:c0 completed [id=0 id_str=]

2024-12-21, again using my custom kernel: This is the next time I went out with
MyPhone. I returned home and opened the laptop's lid at 17:26:40. By then it
should have already connected but it hadn't. So I did a "wpa_reassoc" to see if
that would get my connection working. When it didn't, I stopped the network.
Note that wpa_supplicant is still trying on 5 GHz.

17:27:10.153020 wpa_supplicant 88544 - - wlan0: Trying to associate with
16:84:2d:61:a5:c0 (SSID='MyPhone' freq=5180 MHz)
17:27:10.153977 kernel - - - wlan0: link state changed to DOWN
17:27:10.153944 wpa_supplicant 88544 - - wlan0: CTRL-EVENT-DISCONNECTED
bssid=16:84:2d:61:a5:c0 reason=0
17:27:10.260066 wpa_supplicant 88544 - - wlan0: Trying to associate with
16:84:2d:61:a5:c0 (SSID='MyPhone' freq=5180 MHz)
17:27:20.261243 wpa_supplicant 88544 - - wlan0: Authentication with
16:84:2d:61:a5:c0 timed out.
17:27:20.261287 wpa_supplicant 88544 - - BSSID 16:84:2d:61:a5:c0 ignore list
count incremented to 2, ignoring for 10 seconds
17:27:20.261443 wpa_supplicant 88544 - - wlan0: CTRL-EVENT-DISCONNECTED
bssid=16:84:2d:61:a5:c0 reason=3 locally_generated=1
17:27:20.261511 wpa_supplicant 88544 - - BSSID 16:84:2d:61:a5:c0 ignore list
count incremented to 3, ignoring for 60 seconds
17:27:20.261663 wpa_supplicant 88544 - - wlan0: CTRL-EVENT-DSCP-POLICY
clear_all
17:28:35.410460 wpa_supplicant 88544 - - wlan0: CTRL-EVENT-DSCP-POLICY
clear_all
17:28:35.410600 wpa_supplicant 88544 - - wlan0: CTRL-EVENT-DSCP-POLICY
clear_all
17:28:35.421765 wpa_supplicant 88544 - - ioctl[SIOCS80211, op=95, val=208,
arg_len=0]: Device not configured
17:28:35.421768 wpa_supplicant 88544 - - ioctl[SIOCS80211, op=17, val=0,
arg_len=0]: Device not configured
17:28:35.421771 wpa_supplicant 88544 - - ioctl[SIOCS80211, op=26, val=0,
arg_len=0]: Device not configured
17:28:35.421774 wpa_supplicant 88544 - - ioctl[SIOCS80211, op=16, val=1,
arg_len=0]: Device not configured
17:28:35.421852 devd 1589 - - Processing event '!system=IFNET subsystem=wlan0
type=DETACH'
17:28:35.421896 devd 1589 - - Executing '/home/admin/libexec/netop $'IFNET'
$'wlan0' $'DETACH' $'''
17:28:35.421783 wpa_supplicant 88544 - - wlan0: CTRL-EVENT-TERMINATING
17:28:35.431024 netop 38414 - - call: IFNET wlan0 DETACH
17:28:35.435874 netop 38414 - - run: pkill -F /var/run/wpa_supplicant/wlan0.pid
-x wpa_supplicant

I restarted the network. Notice that wpa_supplicant is now trying to connect on
2.4 GHz. And it panics. At that time MyPhone's hotspot was still running on 5
GHz, so I have no idea why wpa_supplicant tried to use the wrong band.

17:28:40.504580 wpa_supplicant 38474 - - wlan0: Trying to associate with
16:84:2d:61:a5:c0 (SSID='MyPhone' freq=2412 MHz)
17:28:40.571791 kernel - - - iwm0: iwm_rate2ridx: WARNING: device rate for 0
not found!
17:28:40.571869 kernel - - - iwm0: iwm_rate2ridx: WARNING: device rate for 0
not found!
17:28:40.571907 kernel - - - iwm0: iwm_rate2ridx: WARNING: device rate for 0
not found!
17:28:40.571944 kernel - - - iwm0: iwm_rate2ridx: WARNING: device rate for 0
not found!
17:28:40.571981 kernel - - - iwm0: dumping device error log
17:28:40.572020 kernel - - - iwm0: Start Error Log Dump:
17:28:40.572059 kernel - - - iwm0: Status: 0x83, count: 6
17:28:40.572100 kernel - - - iwm0: 0x00002078 | ADVANCED_SYSASSERT
17:28:40.572142 kernel - - - iwm0: 000022F0 | trm_hw_status0
17:28:40.572186 kernel - - - iwm0: 00000000 | trm_hw_status1
17:28:40.572231 kernel - - - iwm0: 00456D06 | branchlink2
17:28:40.572277 kernel - - - iwm0: 0046064A | interruptlink1
17:28:40.572324 kernel - - - iwm0: 00000000 | interruptlink2
17:28:40.572376 kernel - - - iwm0: 00000000 | data1
17:28:40.572426 kernel - - - iwm0: 00000000 | data2
17:28:40.572477 kernel - - - iwm0: DEADBEEF | data3
17:28:40.572530 kernel - - - iwm0: 002A97C3 | beacon time
17:28:40.572584 kernel - - - iwm0: 40625E76 | tsf low
17:28:40.572639 kernel - - - iwm0: 00000029 | tsf hi
17:28:40.572695 kernel - - - iwm0: 00000000 | time gp1
17:28:40.572753 kernel - - - iwm0: 00156DA5 | time gp2
17:28:40.572814 kernel - - - iwm0: 00000001 | uCode revision type
17:28:40.572875 kernel - - - iwm0: 00000022 | uCode version major
17:28:40.572936 kernel - - - iwm0: BA501B11 | uCode version minor
17:28:40.572999 kernel - - - iwm0: 00000312 | hw version
17:28:40.573064 kernel - - - iwm0: 0080FF0F | board version
17:28:40.573129 kernel - - - iwm0: 092E004E | hcmd
17:28:40.573196 kernel - - - iwm0: 00022080 | isr0
17:28:40.573263 kernel - - - iwm0: 00000080 | isr1
17:28:40.573332 kernel - - - iwm0: 08201802 | isr2
17:28:40.573402 kernel - - - iwm0: 004118C0 | isr3
17:28:40.573474 kernel - - - iwm0: 00000000 | isr4
17:28:40.573546 kernel - - - iwm0: 092D002C | last cmd Id
17:28:40.573626 kernel - - - iwm0: 00000000 | wait_event
17:28:40.573647 kernel - - - iwm0: 00000010 | l2p_control
17:28:40.573669 kernel - - - iwm0: 00000020 | l2p_duration
17:28:40.573692 kernel - - - iwm0: 0000003F | l2p_mhvalid
17:28:40.573716 kernel - - - iwm0: 000000CF | l2p_addr_match
17:28:40.573742 kernel - - - iwm0: 0000000D | lmpm_pmg_sel
17:28:40.573769 kernel - - - iwm0: 28020233 | timestamp
17:28:40.573799 kernel - - - iwm0: 00004040 | flow_handler
17:28:40.573829 kernel - - - iwm0: Start UMAC Error Log Dump:
17:28:40.573860 kernel - - - iwm0: Status: 0x83, count: 7
17:28:40.573892 kernel - - - iwm0: 0x00000070 | ADVANCED_SYSASSERT
17:28:40.573925 kernel - - - iwm0: 0x00000000 | umac branchlink1
17:28:40.573960 kernel - - - iwm0: 0xC0087D08 | umac branchlink2
17:28:40.573997 kernel - - - iwm0: 0x010248A0 | umac interruptlink1
17:28:40.574035 kernel - - - iwm0: 0x01028718 | umac interruptlink2
17:28:40.574074 kernel - - - iwm0: 0x00000800 | umac data1
17:28:40.574114 kernel - - - iwm0: 0x01028718 | umac data2
17:28:40.574156 kernel - - - iwm0: 0xDEADBEEF | umac data3
17:28:40.574200 kernel - - - iwm0: 0x00000022 | umac major
17:28:40.574244 kernel - - - iwm0: 0xBA501B11 | umac minor
17:28:40.574290 kernel - - - iwm0: 0xC08875A8 | frame pointer
17:28:40.574337 kernel - - - iwm0: 0xC08875A8 | stack pointer
17:28:40.574386 kernel - - - iwm0: 0x092E004E | last host cmd
17:28:40.574436 kernel - - - iwm0: 0x00000000 | isr status reg
17:28:40.574487 kernel - - - iwm0: driver status:
17:28:40.574540 kernel - - - iwm0:   tx ring  0: qid=0  cur=2   queued=0
17:28:40.574594 kernel - - - iwm0:   tx ring  1: qid=1  cur=0   queued=0
17:28:40.574649 kernel - - - iwm0:   tx ring  2: qid=2  cur=0   queued=0
17:28:40.574706 kernel - - - iwm0:   tx ring  3: qid=3  cur=0   queued=0
17:28:40.574765 kernel - - - iwm0:   tx ring  4: qid=4  cur=0   queued=0
17:28:40.574828 kernel - - - iwm0:   tx ring  5: qid=5  cur=0   queued=0
17:28:40.574889 kernel - - - iwm0:   tx ring  6: qid=6  cur=0   queued=0
17:28:40.574952 kernel - - - iwm0:   tx ring  7: qid=7  cur=0   queued=0
17:28:40.575017 kernel - - - iwm0:   tx ring  8: qid=8  cur=0   queued=0
17:28:40.575083 kernel - - - iwm0:   tx ring  9: qid=9  cur=47  queued=1
17:28:40.575150 kernel - - - iwm0:   tx ring 10: qid=10 cur=0   queued=0
17:28:40.575219 kernel - - - iwm0:   tx ring 11: qid=11 cur=0   queued=0
17:28:40.575290 kernel - - - iwm0:   tx ring 12: qid=12 cur=0   queued=0
17:28:40.575362 kernel - - - iwm0:   tx ring 13: qid=13 cur=0   queued=0
17:28:40.575436 kernel - - - iwm0:   tx ring 14: qid=14 cur=0   queued=0
17:28:40.575516 kernel - - - iwm0:   tx ring 15: qid=15 cur=0   queued=0
17:28:40.575538 kernel - - - iwm0:   tx ring 16: qid=16 cur=0   queued=0
17:28:40.575562 kernel - - - iwm0:   tx ring 17: qid=17 cur=0   queued=0
17:28:40.575586 kernel - - - iwm0:   tx ring 18: qid=18 cur=0   queued=0
17:28:40.575613 kernel - - - iwm0:   tx ring 19: qid=19 cur=0   queued=0
17:28:40.575641 kernel - - - iwm0:   tx ring 20: qid=20 cur=0   queued=0
17:28:40.575670 kernel - - - iwm0:   tx ring 21: qid=21 cur=0   queued=0
17:28:40.575701 kernel - - - iwm0:   tx ring 22: qid=22 cur=0   queued=0
17:28:40.575733 kernel - - - iwm0:   tx ring 23: qid=23 cur=0   queued=0
17:28:40.575767 kernel - - - iwm0:   tx ring 24: qid=24 cur=0   queued=0
17:28:40.575805 kernel - - - iwm0:   tx ring 25: qid=25 cur=0   queued=0
17:28:40.575842 kernel - - - iwm0:   tx ring 26: qid=26 cur=0   queued=0
17:28:40.575881 kernel - - - iwm0:   tx ring 27: qid=27 cur=0   queued=0
17:28:40.575921 kernel - - - iwm0:   tx ring 28: qid=28 cur=0   queued=0
17:28:40.575963 kernel - - - iwm0:   tx ring 29: qid=29 cur=0   queued=0
17:28:40.576006 kernel - - - iwm0:   tx ring 30: qid=30 cur=0   queued=0
17:28:40.576051 kernel - - - iwm0:   rx ring: cur=66
17:28:40.576097 kernel - - - iwm0:   802.11 state 3
17:28:40.576145 kernel - - - iwm0: iwm_intr: controller panicked, iv_state = 3;
restarting
17:28:40.570951 wpa_supplicant 38474 - - wlan0: CTRL-EVENT-DISCONNECTED
bssid=16:84:2d:61:a5:c0 reason=3 locally_generated=1
17:28:41.581325 kernel - - - iwm0: iwm_newstate: IWM_LQ_CMD failed: 35

I have a total of 67 of such panics. Each has 93 iwm0: lines and 25 of them
vary in those 65 panics. And I don't know the driver, so there's no reasonable
way I can analyze them. I'll include them (including the one above) in an
attachment.

Including the iwm panic I just showed, I got 9 panics. The "Trying to
associate" timestamps are: 17:28:40.504580 17:28:45.150464 17:28:49.737945
17:28:54.392337 17:28:58.963140 17:29:03.617191 17:29:08.236658 17:29:12.908324
17:29:17.548844. I then restarted my network and got one panic at
17:29:34.700421. I'm not sure if I did anything special then, but instead of
the expected repeat panics after that one, I got:

17:29:35.773693 wpa_supplicant 39299 - - wlan0: Associated with
16:84:2d:61:a5:c0
17:29:35.773803 kernel - - - wlan0: link state changed to UP
17:29:37.800766 kernel - - - wlan0: link state changed to DOWN
17:29:37.800797 wpa_supplicant 39299 - - wlan0: CTRL-EVENT-DISCONNECTED
bssid=16:84:2d:61:a5:c0 reason=0
17:29:39.837375 kernel - - - iwm0: iwm_auth: failed to set multicast
17:29:39.837511 kernel - - - iwm0: iwm_newstate: could not move to auth state:
35
17:29:39.837540 kernel - - - iwm0: could not initiate scan

I have no idea what those messages might indicate. Anyway, thereafter all I got
from iwm0 was "could not initiate scan", through several net stop and start
cycles. I then unloaded the if_iwm and iwm9000fw modules, which the system
dutifully reloaded. At that point, everything returned to its broken normal. My
next 17 panics were at: 17:43:09.461594 17:43:14.101804 17:43:18.701523
17:43:23.372512 17:43:27.992629 17:43:32.632777 17:43:37.276331 17:43:41.909099
17:44:47.426186 17:44:52.110329 17:44:56.739232 17:45:01.381866 17:45:05.962497
17:45:10.578521 17:45:15.234267 17:45:19.828801 17:45:24.501346. After the last
panic, I got these messages.

17:45:28.707390 kernel - - - iwm0: failed to send antennas before calibration:
35
17:45:28.707515 kernel - - - iwm_run_init_ucode: failed 35
17:45:28.707541 kernel - - - iwm_init_hw failed 35
17:45:28.707563 kernel - - - iwm0: could not initiate scan

The "could not initiate scan" message was all that I saw out of iwm through
17:52:19.922224, after which I restarted my network. That got me 22 more panics
at: 17:52:29.523264 17:52:34.135438 17:52:38.722295 17:52:43.320218
17:52:47.935885 17:52:52.508490 17:52:57.127934 17:53:01.757242 17:53:06.371624
17:53:10.958342 17:53:15.571275 17:53:20.188567 17:53:24.768825 17:53:29.368628
17:53:33.982246 17:53:38.610136 17:53:43.210232 17:53:47.794820 17:53:52.410098
17:53:57.024823 17:54:01.652138 17:54:06.240706. Again I got,

17:54:10.428980 kernel - - - iwm0: failed to send antennas before calibration:
35
17:54:10.429020 kernel - - - iwm_run_init_ucode: failed 35
17:54:10.429037 kernel - - - iwm_init_hw failed 35
17:54:10.429054 kernel - - - iwm0: could not initiate scan

That was all she wrote, again through 18:10:29.738890. I then rebooted my
machine and it was right back to panics, 8 of them: 18:11:02.294667
18:12:03.428172 18:12:08.034539 18:12:12.736892 18:12:17.359661 18:12:22.045198
18:12:26.740529 18:12:31.464267. I rebooted, got a panic at 18:12:31.464267,
which was followed by:

18:12:35.998658 kernel - - - iwm0: iwm_send_phy_db_data: Cannot send HCMD of
Phy DB cfg section, 35
18:12:35.998695 kernel - - - iwm_init_hw failed 35
18:12:35.998715 kernel - - - iwm0: could not initiate scan

Again, I rebooted, got a panic at 18:15:02.025631, followed by:

18:15:06.250812 kernel - - - iwm0: failed to send antennas before calibration:
35
18:15:06.250837 kernel - - - iwm_run_init_ucode: failed 35
18:15:06.250852 kernel - - - iwm_init_hw failed 35
18:15:06.250866 kernel - - - iwm0: could not initiate scan

Again, I rebooted and got 9 more panics: 18:19:19.529518 18:19:24.254847
18:19:28.955165 18:19:33.571993 18:19:38.175545 18:19:42.887308 18:19:47.555632
18:19:52.264708 18:19:57.007505, again followed by:

18:20:01.287715 kernel - - - iwm0: failed to send antennas before calibration:
35
18:20:01.287740 kernel - - - iwm_run_init_ucode: failed 35
18:20:01.287751 kernel - - - iwm_init_hw failed 35
18:20:01.287762 kernel - - - iwm0: could not initiate scan

At that point, I gave up on using my hotspot and switched to a USB tether.
That's when I read the bug report that suggested that the band was an issue. So
I told MyPhone to use 2.4 GHz and wpa_supplicant reported "wlan0: Trying to
associate with 7a:a7:4f:79:2a:fe (SSID='MyPhone' freq=2462 MHz)" and the
connection proceeded normally. I then told MyPhone to use 5 GHz and
wpa_supplicant reported "wlan0: Trying to associate with 8a:c6:22:f7:63:06
(SSID='MyPhone' freq=5745 MHz)" and again the connection proceeded normally. It
has remained stable since.

-- 
You are receiving this mail because:
You are the assignee for the bug.