Bug 197039

Summary: iwlwifi: 8260: TFD Q hang upon power save toggling - WIFILNX-1785
Product: Drivers Reporter: Francisco Cribari (cribari)
Component: network-wirelessAssignee: DO NOT USE - assign "network-wireless-intel" component instead (linuxwifi)
Status: CLOSED UNREPRODUCIBLE    
Severity: high CC: cribari, george.sapkin, goodmirek, janek+kernel, jaya.p.g, jccantele49, joss, kernel.org, languitar, luca
Priority: P1    
Hardware: x86-64   
OS: Linux   
See Also: https://bugzilla.kernel.org/show_bug.cgi?id=197061
https://bugzilla.kernel.org/show_bug.cgi?id=197147
Kernel Version: 4.13.3 Subsystem:
Regression: Yes Bisected commit-id:
Attachments: Hardware description
8260 firmware with debug enabled
8265 firmware with debug enabled
Fix candidate
New BT firmware
latest Core28 with debug
latest Core28 with debug

Description Francisco Cribari 2017-09-25 19:56:30 UTC
Created attachment 258599 [details]
Hardware description

I run Manjaro KDE (which is Arch-based). My notebook has an Intel 8260 wifi/bluetooth chipset. After linux-firmware was upgraded to version linux-firmware 20170907.a61ac5c-1 I started experiencing bluetoth radom disconnects and bluetooth crashes with kernel 4.13.x and 4.14 RC1 (but not with the LTS kernel, 4.9.51). The hardware description is the attached file. 

*

My full journal (the output of journalctl --boot) can be found at 

https://pastebin.com/2DJM1zKn

and output journalctl --boot | grep -i blue is available at 

https://pastebin.com/4MtxVeEz

I reverted back to linux-firmware version 20170622.7d2c913-1 and the bluetooth crashes stopped. I thus believe there may be a bug in the latest linux-firmware.
Comment 1 G Jaya Praveen 2017-09-27 07:09:01 UTC
Hi,

Can you please share the scenario, where you see the issue?

And also, FW you have got from Linux-firmware?
This is the last fw in the Linux firmware tree:
2017-03-07 linux-firmware: Update firmware patch for Intel Bluetooth,8260 

But from your description, i see a different version.

Can you please give the output of the fw version:
$sudo hcitool cmd 3f 05

Thanks.
Comment 2 Francisco Cribari 2017-09-27 09:57:36 UTC
Hi. With the previous (Arch) version of linux-firmware (20170622.7d2c913-1) I experience no bluetooth crashes. With the current version (20170907.a61ac5c-1) and recent kernels, however, bluetooth crashes after I use a bluetooth mouse for a while. After the crash I see 

[cribari@darwin5 ~]$ sudo systemctl status bluetooth
● bluetooth.service - Bluetooth service
   Loaded: loaded (/usr/lib/systemd/system/bluetooth.service; enabled; vendor preset: disabled)
   Active: active (running) since Wed 2017-09-27 05:39:24 -03; 1h 9min ago
     Docs: man:bluetoothd(8)
 Main PID: 615 (bluetoothd)
   Status: "Running"
    Tasks: 1 (limit: 4915)
   CGroup: /system.slice/bluetooth.service
           └─615 /usr/lib/bluetooth/bluetoothd

set 27 05:39:24 darwin5 systemd[1]: Started Bluetooth service.
set 27 05:39:24 darwin5 bluetoothd[615]: Bluetooth management interface 1.14 initialized
set 27 05:39:31 darwin5 bluetoothd[615]: Endpoint registered: sender=:1.37 path=/MediaEndpoint/A2DPSource
set 27 05:39:31 darwin5 bluetoothd[615]: Endpoint registered: sender=:1.37 path=/MediaEndpoint/A2DPSink
set 27 05:55:47 darwin5 bluetoothd[615]: bt_uhid_send: Invalid argument (22)
set 27 05:55:47 darwin5 bluetoothd[615]: bt_uhid_send: Invalid argument (22)
set 27 05:55:47 darwin5 bluetoothd[615]: bt_uhid_send: Invalid argument (22)
set 27 05:55:47 darwin5 bluetoothd[615]: bt_uhid_send: Invalid argument (22)
set 27 05:55:47 darwin5 bluetoothd[615]: bt_uhid_send: Invalid argument (22)
set 27 05:55:47 darwin5 bluetoothd[615]: bt_uhid_send: Invalid argument (22)

The output of sudo hcitool cmd 3f 05 (before bluetooth crashes) is 

[cribari@darwin5 ~]$ sudo hcitool cmd 3f 05
< HCI Command: ogf 0x3f, ocf 0x0005, plen 0
> HCI Event: 0x0e plen 13
  01 05 FC 00 37 0B 12 23 00 76 32 10 00 

After the bluetooth crash I only see 

[cribari@darwin5 ~]$ sudo hcitool cmd 3f 05
< HCI Command: ogf 0x3f, ocf 0x0005, plen 0

Information on the kernel version and on the version of linux-firmware:
[cribari@darwin5 ~]$ uname -a
Linux darwin5 4.13.3-2-MANJARO #1 SMP PREEMPT Wed Sep 20 15:53:16 UTC 2017 x86_64 GNU/Linux

[cribari@darwin5 ~]$ sudo pacman -Qi linux-firmware
Name            : linux-firmware
Version         : 20170907.a61ac5c-1
Description     : Firmware files for Linux
Architecture    : any
URL             : http://git.kernel.org/?p=linux/kernel/git/firmware/linux-firmware.git;a=summary
Licenses        : GPL2  GPL3  custom
Groups          : None
Provides        : None
Depends On      : None
Optional Deps   : None
Required By     : linux412  linux413  linux414  linux49
Optional For    : None
Conflicts With  : linux-firmware-git  kernel26-firmware  ar9170-fw  iwlwifi-1000-ucode
                  iwlwifi-3945-ucode  iwlwifi-4965-ucode  iwlwifi-5000-ucode  iwlwifi-5150-ucode
                  iwlwifi-6000-ucode  rt2870usb-fw  rt2x00-rt61-fw  rt2x00-rt71w-fw  amd-ucode
Replaces        : kernel26-firmware  ar9170-fw  iwlwifi-1000-ucode  iwlwifi-3945-ucode
                  iwlwifi-4965-ucode  iwlwifi-5000-ucode  iwlwifi-5150-ucode  iwlwifi-6000-ucode
                  rt2870usb-fw  rt2x00-rt61-fw  rt2x00-rt71w-fw  amd-ucode
Installed Size  : 208,06 MiB
Packager        : Bartlomiej Piotrowski <bpiotrowski@archlinux.org>
Build Date      : sex 08 set 2017 08:43:01 -03
Install Date    : qua 27 set 2017 05:37:34 -03
Install Reason  : Explicitly installed
Install Script  : No
Validated By    : Signature

Does that help?
Comment 3 Francisco Cribari 2017-09-27 10:03:21 UTC
More information: 

[cribari@darwin5 ~]$ uname -a; lspci -nnk | grep -iA2 net; lsusb; dmesg | grep -i bluetooth; dmesg | grep -i firmware; lsmod | grep bluetooth > bluetoth-ingo-after-crash.txt
Linux darwin5 4.13.3-2-MANJARO #1 SMP PREEMPT Wed Sep 20 15:53:16 UTC 2017 x86_64 GNU/Linux
01:00.0 Network controller [0280]: Intel Corporation Wireless 8260 [8086:24f3] (rev 3a)
        Subsystem: Intel Corporation Device [8086:9010]
        Kernel driver in use: iwlwifi
--
02:00.0 Ethernet controller [0200]: Realtek Semiconductor Co., Ltd. RTL8111/8168/8411 PCI Express Gigabit Ethernet Controller [10ec:8168] (rev 15)
        Subsystem: Samsung Electronics Co Ltd Device [144d:c136]
        Kernel driver in use: r8168
Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 001 Device 003: ID 2232:1079 Silicon Motion 
Bus 001 Device 002: ID 8087:0a2b Intel Corp. 
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
[    3.867300] Bluetooth: Core ver 2.22
[    3.867349] Bluetooth: HCI device and connection manager initialized
[    3.867354] Bluetooth: HCI socket layer initialized
[    3.867356] Bluetooth: L2CAP socket layer initialized
[    3.867364] Bluetooth: SCO socket layer initialized
[    3.874904] Bluetooth: hci0: Firmware revision 0.0 build 118 week 50 2016
[    3.909029] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[    3.909031] Bluetooth: BNEP filters: protocol multicast
[    3.909034] Bluetooth: BNEP socket layer initialized
[   11.312017] Bluetooth: RFCOMM TTY layer initialized
[   11.312022] Bluetooth: RFCOMM socket layer initialized
[   11.312027] Bluetooth: RFCOMM ver 1.11
[  101.327640] Bluetooth: HIDP (Human Interface Emulation) ver 1.2
[  101.327644] Bluetooth: HIDP socket layer initialized
[  101.330140] input: HP Bluetooth Mouse Z6000 as /devices/pci0000:00/0000:00:14.0/usb1/1-5/1-5:1.0/bluetooth/hci0/hci0:256/0005:03F0:074C.0002/input/input20
[  101.330246] hid-generic 0005:03F0:074C.0002: input,hidraw1: BLUETOOTH HID v1.29 Mouse [HP Bluetooth Mouse Z6000] on 00:c2:c6:cf:a5:25
[  922.484371] hid-generic 0005:413C:301E.0003: input,hidraw2: BLUETOOTH HID v0.01 Mouse [Dell WM527 Mouse] on 00:C2:C6:CF:A5:25
[  987.240372] hid-generic 0005:2717:0040.0004: input,hidraw3: BLUETOOTH HID v0.23 Mouse [MiMouse] on 00:C2:C6:CF:A5:25
[ 1213.697987] input: HP Bluetooth Mouse Z6000 as /devices/pci0000:00/0000:00:14.0/usb1/1-5/1-5:1.0/bluetooth/hci0/hci0:256/0005:03F0:074C.0005/input/input23
[ 1213.703072] hid-generic 0005:03F0:074C.0005: input,hidraw1: BLUETOOTH HID v1.29 Mouse [HP Bluetooth Mouse Z6000] on 00:c2:c6:cf:a5:25
[    0.456685] ACPI: [Firmware Bug]: BIOS _OSI(Linux) query ignored
[    2.665915] iwlwifi 0000:01:00.0: Direct firmware load for iwlwifi-8000C-33.ucode failed with error -2
[    2.665929] iwlwifi 0000:01:00.0: Direct firmware load for iwlwifi-8000C-32.ucode failed with error -2
[    2.672744] iwlwifi 0000:01:00.0: loaded firmware version 31.532993.0 op_mode iwlmvm
[    2.675204] [drm] Finished loading DMC firmware i915/skl_dmc_ver1_26.bin (v1.26)
[    3.874904] Bluetooth: hci0: Firmware revision 0.0 build 118 week 50 2016
Comment 4 G Jaya Praveen 2017-09-27 10:41:35 UTC
Hi,

Can you please share the complete dmesg log and syslogs (/var/logs/syslogs).
From this log, it looks to be wifi issue, don't see any Bluetooth related issue.

Thanks.
Comment 5 G Jaya Praveen 2017-09-27 11:36:36 UTC
Also one more thing, can you disable wifi and just use Bluetooth and connect with the BT mouse and check if you still the issue.
Please check and update your results along with the logs (dmesg and syslog) for the failure case.
Comment 6 Francisco Cribari 2017-09-27 13:29:09 UTC
Hi. Here is the information you requested: 

https://pastebin.com/e4QjwbUk

Could the problem be related to this one? 

https://www.spinics.net/lists/linux-wireless/msg166025.html

I will try to disable wifi and use bluetooth and I'll report back on that.
Comment 7 Francisco Cribari 2017-09-27 13:43:48 UTC
Disabling wifi I was able to use a bluetooth mouse without crashes. The dmesg info for this case is available at 

https://pastebin.com/eQ1MTmGF

BTW, as soon as I turned wifi on my bluetooth mouse stopped working. At that point: 

[cribari@darwin5 ~]$ sudo systemctl status bluetooth
● bluetooth.service - Bluetooth service                                                                                                       
   Loaded: loaded (/usr/lib/systemd/system/bluetooth.service; enabled; vendor preset: disabled)                                               
   Active: active (running) since Wed 2017-09-27 10:30:10 -03; 10min ago
     Docs: man:bluetoothd(8)
 Main PID: 616 (bluetoothd)
   Status: "Running"
    Tasks: 1 (limit: 4915)
   CGroup: /system.slice/bluetooth.service
           └─616 /usr/lib/bluetooth/bluetoothd

set 27 10:30:19 darwin5 bluetoothd[616]: Endpoint registered: sender=:1.50 path=/MediaEndpoint/A2DPSource
set 27 10:30:19 darwin5 bluetoothd[616]: Endpoint registered: sender=:1.50 path=/MediaEndpoint/A2DPSink
set 27 10:38:36 darwin5 bluetoothd[616]: Can't get HIDP connection info
set 27 10:38:42 darwin5 bluetoothd[616]: connect error: Host is down (112)
set 27 10:39:06 darwin5 bluetoothd[616]: Can't get HIDP connection info
set 27 10:39:12 darwin5 bluetoothd[616]: connect error: Host is down (112)
set 27 10:39:36 darwin5 bluetoothd[616]: Can't get HIDP connection info
set 27 10:39:42 darwin5 bluetoothd[616]: connect error: Host is down (112)
set 27 10:40:06 darwin5 bluetoothd[616]: Can't get HIDP connection info
set 27 10:40:12 darwin5 bluetoothd[616]: connect error: Host is down (112)


Interestingly, I do not experience any crashes when: (i) I use the latest firmware (20170907.a61ac5c-1) together with the LTS kernel (4.9.X), (ii) I use the previous firmware (20170622.7d2c913-1) with the most recent kernels (4.13.X and 4.14 RC1). The crashes take place when I use the latest firmware together with the latest kernels.
Comment 8 Emmanuel Grumbach 2017-09-27 14:47:37 UTC
Hi,

We will provide a debug firmware to collect debug data from the WiFi side.
How easily can you reproduce this:

[   88.796807] iwlwifi 0000:01:00.0: Microcode SW error detected.  Restarting 0x2000000.
[   88.796968] iwlwifi 0000:01:00.0: Start IWL Error Log Dump:
[   88.796976] iwlwifi 0000:01:00.0: Status: 0x00000200, count: 6
[   88.796982] iwlwifi 0000:01:00.0: Loaded firmware version: 31.532993.0
[   88.796989] iwlwifi 0000:01:00.0: 0x00000084 | NMI_INTERRUPT_UNKNOWN  


?

This means that the WiFi transmit queues are stuck and it is a good trigger point to collect the debug logs. The question is whether you see this a lot or not.
Do you have this anytime you can't work with BT, or?
Comment 9 Francisco Cribari 2017-09-27 14:59:07 UTC
Hi. I haven't looked at many dmesg dumps, but I've faced many crashes lately. I thus imagine that it is reproducible. If you give me a new firmware and instructions on how to install/use it (and collect the necessary data), I'll be glad to give it a try. A couple of comments: 1) I run Manjaro Linux and I initially reported the problem in their forum: 

https://forum.manjaro.org/t/bluetooth-crashes-since-updated-to-kernel-4-13-2/31809

2) I disabled bluetooth coexistence (bt_coex_active=0) about an hour ago (and rebooted) and since then I have not experienced any crashes.
Comment 10 Jacob C 2017-09-27 16:06:38 UTC
I can confirm that I'm also having the same issue as Francisco above, also on Manjaro.

My hardware is slightly different, Intel Corporation Wireless 8265.
Comment 11 Emmanuel Grumbach 2017-09-27 17:25:05 UTC
Created attachment 258619 [details]
8260 firmware with debug enabled

Hi,

Here is the firmware for 8260. Please copy it to /lib/firmware (I assume your distro takes it from there), you can backup the existing one before you overriding it.

The instructions on how to collect the data are here:
https://wireless.wiki.kernel.org/en/users/drivers/iwlwifi/debugging#firmware_debugging

Please take the time to read the privacy notice:
https://wireless.wiki.kernel.org/en/users/drivers/iwlwifi/debugging#privacy_aspects

Note that I reduced the timeout to 700ms to collect the data closer to the issue.

Of course, please re-enable bt coex.

With the results, I'll need to involve the WiFi firmware team. This can take time.

Thank you.
Comment 12 Emmanuel Grumbach 2017-09-27 17:26:16 UTC
Created attachment 258621 [details]
8265 firmware with debug enabled

Same as previous comment, but for 8265.
Comment 13 Francisco Cribari 2017-09-28 00:11:03 UTC
Hi. dmesg info after crash (with customized firmware and debugging): 

https://pastebin.com/kSwpjMME

ifw-fw-error dump: 

https://www.dropbox.com/s/r11loc2c5y66skm/iwl-fw-error_2017-09-27.zip?dl=0

Does that help?
Comment 14 Emmanuel Grumbach 2017-09-28 04:06:18 UTC
Hmm.. That will probably help (will need to forward this to the firmware team), but this is not the same problem: you know hit this:

[ 3263.040021] iwlwifi 0000:01:00.0: Loaded firmware version: 31.560484.0
[ 3263.040023] iwlwifi 0000:01:00.0: 0x0000307C | ADVANCED_SYSASSERT
Comment 15 Emmanuel Grumbach 2017-09-28 05:04:03 UTC
I looked at the 2 dumps that you had in Dropbox.
One of them has been created manually it seems and I'll need your explanation on what happened when you create it (no BT, no WiFi, etc...). The firmware didn't crash by itself in that dump.
Along with that, I can seee a dump for the ASSERT 370C which is good.
Note that ASSERT 307C has nothing to do with BT, and therefore, I'll ask you to open a new bug, paste the dmesg output and the link to the dump in that new bug.
Please CC linuxwifi@intel.com on that new bug.

Thank you.
Comment 16 Francisco Cribari 2017-09-28 10:42:10 UTC
Hi. Thank you. I filed an new bug report: 

https://bugzilla.kernel.org/show_bug.cgi?id=197061

The dump files were created by the udev rule that I created following the instructions available at 

https://wireless.wiki.kernel.org/en/users/drivers/iwlwifi/debugging#firmware_debugging

I don't recall what happened with the first one. I may have forgotten to issue 

echo 1 > /sys/kernel/debug/iwlwifi/0000\:0X\:00.0/iwlmvm/fw_dbg_collect

I decided to make both files available because there could be valuable information in the first dump file. 

I am dutifully reporting a bug I am facing. I hope the information I am providing proves to be useful for locating the problem and fixing it.
Comment 17 Emmanuel Grumbach 2017-09-28 11:02:43 UTC
(In reply to Francisco Cribari from comment #16)
> Hi. Thank you. I filed an new bug report: 
> 
> https://bugzilla.kernel.org/show_bug.cgi?id=197061

Yup - saw that. Thanks.

> 
> I don't recall what happened with the first one. I may have forgotten to
> issue 
> 
> echo 1 > /sys/kernel/debug/iwlwifi/0000\:0X\:00.0/iwlmvm/fw_dbg_collect

You shouldn't issue that command since you have a firmware crash and that collects automatically the data. No need to ask the driver to collect the data manually.

> 
> I am dutifully reporting a bug I am facing. I hope the information I am
> providing proves to be useful for locating the problem and fixing it.

Data was sent to the firmware team for analysis.
Comment 18 Emmanuel Grumbach 2017-11-14 12:11:46 UTC
Created attachment 260651 [details]
Fix candidate

Hi,

here is a fix candidate from the firmware team.

Please test.

Thanks!
Comment 19 Francisco Cribari 2017-11-14 14:41:31 UTC
I am using the candidate firmware with BT coexistence enabled. Bluetooth crashed. See information below. What other information can I provide? 

From dmesg: 

[   19.663720] Bluetooth: HIDP (Human Interface Emulation) ver 1.2
[   19.663724] Bluetooth: HIDP socket layer initialized
[   19.666238] hid-generic 0005:03F0:074C.0002: unknown main item tag 0x0
[   19.666344] input: HP Bluetooth Mouse Z6000 as /devices/pci0000:00/0000:00:14.0/usb1/1-5/1-5:1.0/bluetooth/hci0/hci0:256/0005:03F0:074C.0002/input/input20
[   19.666449] hid-generic 0005:03F0:074C.0002: input,hidraw1: BLUETOOTH HID v1.29 Mouse [HP Bluetooth Mouse Z6000] on 00:c2:c6:cf:a5:25
[   28.315619] wlp1s0: authenticate with 70:3a:cb:29:33:a3
[   28.324801] wlp1s0: send auth to 70:3a:cb:29:33:a3 (try 1/3)
[   28.331920] wlp1s0: authenticated
[   28.333504] wlp1s0: associate with 70:3a:cb:29:33:a3 (try 1/3)
[   28.336181] wlp1s0: RX AssocResp from 70:3a:cb:29:33:a3 (capab=0x11 status=0 aid=2)
[   28.338075] wlp1s0: associated
[   28.338127] IPv6: ADDRCONF(NETDEV_CHANGE): wlp1s0: link becomes ready
[ 1515.014923] [drm:intel_pipe_update_end [i915]] *ERROR* Atomic update failure on pipe A (start=91861 end=91862) time 181 us, min 1073, max 1079, scanline start 1068, end 1080                              
[ 7665.709780] wlp1s0: disconnect from AP 70:3a:cb:29:33:a3 for new auth to 70:3a:cb:29:33:a7
[ 7665.713932] wlp1s0: authenticate with 70:3a:cb:29:33:a7
[ 7665.717288] wlp1s0: send auth to 70:3a:cb:29:33:a7 (try 1/3)
[ 7665.826710] wlp1s0: send auth to 70:3a:cb:29:33:a7 (try 2/3)
[ 7665.829821] wlp1s0: authenticated
[ 7665.830041] wlp1s0: associate with 70:3a:cb:29:33:a7 (try 1/3)
[ 7665.836240] wlp1s0: RX AssocResp from 70:3a:cb:29:33:a7 (capab=0x431 status=0 aid=2)
[ 7665.839026] wlp1s0: associated
[ 7671.377173] usb 1-5: reset full-speed USB device number 2 using xhci_hcd

[ 7748.086893] Bluetooth: hci0 command 0x0804 tx timeout
[ 7788.085915] wlp1s0: disconnect from AP 70:3a:cb:29:33:a7 for new auth to 70:3a:cb:29:33:a3
[ 7788.095624] wlp1s0: authenticate with 70:3a:cb:29:33:a3
[ 7788.104059] wlp1s0: send auth to 70:3a:cb:29:33:a3 (try 1/3)
[ 7788.108813] wlp1s0: authenticated
[ 7788.110025] wlp1s0: associate with 70:3a:cb:29:33:a3 (try 1/3)
[ 7788.112877] wlp1s0: RX AssocResp from 70:3a:cb:29:33:a3 (capab=0x11 status=0 aid=2)
[ 7788.116382] wlp1s0: associated
[ 7919.645783] Bluetooth: hci0 link tx timeout
[ 7919.645802] Bluetooth: hci0 killing stalled connection 08:b7:38:70:09:38
[ 7921.740026] Bluetooth: hci0 command 0x041f tx timeout
[ 7923.873206] Bluetooth: hci0 command 0x0406 tx timeout
[ 7924.892021] Bluetooth: hci0 link tx timeout
[ 7924.892062] Bluetooth: hci0 killing stalled connection 08:b7:38:70:09:38
[ 7999.057979] Bluetooth: hci0 link tx timeout
[ 7999.057985] Bluetooth: hci0 killing stalled connection 08:b7:38:70:09:38
[ 8004.086679] Bluetooth: hci0 link tx timeout
[ 8004.086699] Bluetooth: hci0 killing stalled connection 08:b7:38:70:09:38
[ 8009.372477] Bluetooth: hci0 link tx timeout
[ 8009.372490] Bluetooth: hci0 killing stalled connection 08:b7:38:70:09:38
[ 8018.982078] Bluetooth: hci0 link tx timeout
[ 8018.982087] Bluetooth: hci0 killing stalled connection 08:b7:38:70:09:38
[ 8024.298025] Bluetooth: hci0 link tx timeout
[ 8024.298041] Bluetooth: hci0 killing stalled connection 08:b7:38:70:09:38
[ 8032.141643] Bluetooth: hci0 link tx timeout
[ 8032.141657] Bluetooth: hci0 killing stalled connection 08:b7:38:70:09:38
[ 8037.323437] Bluetooth: hci0 link tx timeout
[ 8037.323452] Bluetooth: hci0 killing stalled connection 08:b7:38:70:09:38
[ 8084.065348] Bluetooth: hci0 link tx timeout
[ 8084.065366] Bluetooth: hci0 killing stalled connection 08:b7:38:70:09:38
[ 8089.368431] Bluetooth: hci0 link tx timeout
[ 8089.368448] Bluetooth: hci0 killing stalled connection 08:b7:38:70:09:38

[cribari@darwin5 ~]$ systemctl status bluetooth
● bluetooth.service - Bluetooth service
   Loaded: loaded (/usr/lib/systemd/system/bluetooth.service; enabled; vendor preset: disabled)
   Active: active (running) since Tue 2017-11-14 09:19:10 -03; 2h 17min ago
     Docs: man:bluetoothd(8)
 Main PID: 606 (bluetoothd)
   Status: "Running"
    Tasks: 1 (limit: 4915)
   CGroup: /system.slice/bluetooth.service
           └─606 /usr/lib/bluetooth/bluetoothd

nov 14 09:19:10 darwin5 systemd[1]: Starting Bluetooth service...
nov 14 09:19:10 darwin5 bluetoothd[606]: Bluetooth daemon 5.47
nov 14 09:19:10 darwin5 systemd[1]: Started Bluetooth service.
nov 14 09:19:10 darwin5 bluetoothd[606]: Starting SDP server
nov 14 09:19:10 darwin5 bluetoothd[606]: Bluetooth management interface 1.14 initialized
nov 14 09:19:18 darwin5 bluetoothd[606]: Endpoint registered: sender=:1.39 path=/MediaEndpoint/A2DPSource
nov 14 09:19:18 darwin5 bluetoothd[606]: Endpoint registered: sender=:1.39 path=/MediaEndpoint/A2DPSink
nov 14 10:07:00 darwin5 bluetoothd[606]: Unable to get io data for Object Push: getpeername: Transport endpoint is not connected (107)
nov 14 10:21:48 darwin5 bluetoothd[606]: Unable to get io data for Object Push: getpeername: Transport endpoint is not connected (107)

kernel: 

[cribari@darwin5 ~]$ uname -a
Linux darwin5 4.13.12-1-MANJARO #1 SMP PREEMPT Wed Nov 8 10:52:53 UTC 2017 x86_64 GNU/Linux
Comment 20 Francisco Cribari 2017-11-21 01:01:04 UTC
I noticed the dmesg error messages below (Intel 8260 w/ BT coexistence off). Could they be related to the current bug?  

[53203.022533] IPv6: ADDRCONF(NETDEV_CHANGE): wlp1s0: link becomes ready
[55269.768626] iwlwifi 0000:01:00.0: Queue 11 is active on fifo 1 and stuck for 10000 ms. SW [162, 211] HW [162, 211] FH TRB=0x0c010b0b1                                              
[55269.768769] iwlwifi 0000:01:00.0: Microcode SW error detected.  Restarting 0x2000000.   
[55269.768941] iwlwifi 0000:01:00.0: Start IWL Error Log Dump:                             
[55269.768952] iwlwifi 0000:01:00.0: Status: 0x00000200, count: 6                          
[55269.768961] iwlwifi 0000:01:00.0: Loaded firmware version: 31.622545.1                  
[55269.768973] iwlwifi 0000:01:00.0: 0x00000084 | NMI_INTERRUPT_UNKNOWN                    
[55269.768983] iwlwifi 0000:01:00.0: 0x00000230 | trm_hw_status0                           
[55269.768991] iwlwifi 0000:01:00.0: 0x00000000 | trm_hw_status1                           
[55269.768999] iwlwifi 0000:01:00.0: 0x0001011C | branchlink2                              
[55269.769009] iwlwifi 0000:01:00.0: 0x00028EB2 | interruptlink1                           
[55269.769018] iwlwifi 0000:01:00.0: 0x00028EB2 | interruptlink2                           
[55269.769026] iwlwifi 0000:01:00.0: 0x00000000 | data1                                    
[55269.769035] iwlwifi 0000:01:00.0: 0x00000080 | data2                                    
[55269.769044] iwlwifi 0000:01:00.0: 0x07830000 | data3                                    
[55269.769054] iwlwifi 0000:01:00.0: 0xA58145AC | beacon time                              
[55269.769063] iwlwifi 0000:01:00.0: 0x6524AA20 | tsf low                                  
[55269.769072] iwlwifi 0000:01:00.0: 0x00000223 | tsf hi                                   
[55269.769081] iwlwifi 0000:01:00.0: 0x00000000 | time gp1                                 
[55269.769090] iwlwifi 0000:01:00.0: 0x7B64B32B | time gp2                                 
[55269.769099] iwlwifi 0000:01:00.0: 0x00000001 | uCode revision type                      
[55269.769109] iwlwifi 0000:01:00.0: 0x0000001F | uCode version major                      
[55269.769118] iwlwifi 0000:01:00.0: 0x00097FD1 | uCode version minor                      
[55269.769128] iwlwifi 0000:01:00.0: 0x00000201 | hw version                               
[55269.769137] iwlwifi 0000:01:00.0: 0x00C89008 | board version                            
[55269.769146] iwlwifi 0000:01:00.0: 0x009B019C | hcmd                                     
[55269.769155] iwlwifi 0000:01:00.0: 0x24022006 | isr0                                     
[55269.769164] iwlwifi 0000:01:00.0: 0x00800000 | isr1                                     
[55269.769173] iwlwifi 0000:01:00.0: 0x0800180A | isr2                                     
[55269.769182] iwlwifi 0000:01:00.0: 0x004144C0 | isr3                                     
[55269.769191] iwlwifi 0000:01:00.0: 0x00000000 | isr4                                     
[55269.769201] iwlwifi 0000:01:00.0: 0xA9CC009D | last cmd Id                              
[55269.769210] iwlwifi 0000:01:00.0: 0x00000000 | wait_event                               
[55269.769219] iwlwifi 0000:01:00.0: 0x00000080 | l2p_control                              
[55269.769228] iwlwifi 0000:01:00.0: 0x00010030 | l2p_duration                             
[55269.769237] iwlwifi 0000:01:00.0: 0x0000003F | l2p_mhvalid                              
[55269.769246] iwlwifi 0000:01:00.0: 0x00000080 | l2p_addr_match                           
[55269.769254] iwlwifi 0000:01:00.0: 0x0000000D | lmpm_pmg_sel                             
[55269.769263] iwlwifi 0000:01:00.0: 0x14111330 | timestamp                                
[55269.769271] iwlwifi 0000:01:00.0: 0x00344860 | flow_handler                             
[55269.769349] iwlwifi 0000:01:00.0: Start IWL Error Log Dump:                             
[55269.769359] iwlwifi 0000:01:00.0: Status: 0x00000200, count: 7                          
[55269.769370] iwlwifi 0000:01:00.0: 0x00000070 | ADVANCED_SYSASSERT
[55269.769379] iwlwifi 0000:01:00.0: 0x00000000 | umac branchlink1
[55269.769387] iwlwifi 0000:01:00.0: 0xC0086B6C | umac branchlink2
[55269.769396] iwlwifi 0000:01:00.0: 0xC00844E8 | umac interruptlink1
[55269.769404] iwlwifi 0000:01:00.0: 0xC00844E8 | umac interruptlink2
[55269.769413] iwlwifi 0000:01:00.0: 0x00000800 | umac data1
[55269.769422] iwlwifi 0000:01:00.0: 0xC00844E8 | umac data2
[55269.769431] iwlwifi 0000:01:00.0: 0xDEADBEEF | umac data3
[55269.769440] iwlwifi 0000:01:00.0: 0x0000001F | umac major
[55269.769448] iwlwifi 0000:01:00.0: 0x00097FD1 | umac minor
[55269.769457] iwlwifi 0000:01:00.0: 0xC088628C | frame pointer
[55269.769467] iwlwifi 0000:01:00.0: 0xC088628C | stack pointer
[55269.769475] iwlwifi 0000:01:00.0: 0x009B019C | last host cmd
[55269.769483] iwlwifi 0000:01:00.0: 0x00000000 | isr status reg
[55269.769498] ieee80211 phy0: Hardware restart was requested
[59467.338533] wlp1s0: failed to remove key (2, ff:ff:ff:ff:ff:ff) from hardware (-22)
[59470.640165] wlp1s0: authenticate with 70:3a:cb:29:30:00
[59470.648250] wlp1s0: send auth to 70:3a:cb:29:30:00 (try 1/3)
[59470.657616] wlp1s0: authenticated
[59470.661795] wlp1s0: associate with 70:3a:cb:29:30:00 (try 1/3)
[59470.671412] wlp1s0: RX AssocResp from 70:3a:cb:29:30:00 (capab=0x431 status=0 aid=1)
[59470.674762] wlp1s0: associated

[cribari@darwin5 ~]$ uname -a
Linux darwin5 4.13.14-2-MANJARO #1 SMP PREEMPT Sat Nov 18 14:25:40 UTC 2017 x86_64 GNU/Linux
Comment 21 Francisco Cribari 2017-11-21 01:15:34 UTC
More on the above errors: Firmware used is iwlwifi-8000C-31.ucode (from linux-firmware version 20171009.bf04291-1, Arch package). I do not have a dump file since I was not running a customized debugging firmware.
Comment 22 Emmanuel Grumbach 2017-11-21 22:17:40 UTC
Yes, this is a TFD queue hang.
Comment 23 Emmanuel Grumbach 2017-11-27 13:02:59 UTC
Created attachment 260897 [details]
New BT firmware

Here is a pre-release of the new firmware for BT.
Please copy the files to /lib/firmware/intel/

You'll need a hard power off / on cycle.

After boot,  run btmon in 1 terminal and in the other terminal give the command hcitool cmd 3f 05 in root permission.
After giving the hcitool cmd 3f 05 the btmon log will show the version information.

Please provide the btmon log.

Let us know if things feel better.

Note: this includes BT firmware for 8260 and 8265.
Comment 24 Francisco Cribari 2017-11-27 15:59:06 UTC
@Emmanuel Grumbach Here is the btmon log (Intel 8260 with BT coex on): 

https://pastebin.com/cCfBDLms

Does it help?
Comment 25 Emmanuel Grumbach 2017-11-27 16:09:49 UTC
Need to ask the BT guys.

Do you still have the wifi crash with this BT firmware?
Comment 26 Francisco Cribari 2017-11-27 18:58:16 UTC
@Emmanuel Grumbach No crashes so far (Intel 8260 com BT coex on and the new BT firmware).
Comment 27 Emmanuel Grumbach 2017-11-27 19:29:47 UTC
great - how often could you repro the crash before?
Comment 28 Francisco Cribari 2017-11-27 22:14:14 UTC
@Emmanuel Grumbach I have been using the testing firmware (w/ BT coex on) for about 8 hours and so far no crashes. Before crashes would take place in a couple of hours. So far so good.
Comment 29 Francisco Cribari 2017-11-27 23:18:55 UTC
@Emmanuel Grumbach My computer has experienced a crash. I don't know whether it was BT-related. The dump info is available at 

https://www.dropbox.com/s/g224p9srtar6rgo/btmon-2.out.gz?dl=0
Comment 30 Emmanuel Grumbach 2017-11-28 03:21:30 UTC
Please attach dmesg as well.
Comment 31 Francisco Cribari 2017-11-28 10:21:41 UTC
@Emmanuel Grumbach dmesg info available at https://pastebin.com/u8PTMhi8 .
Comment 32 Emmanuel Grumbach 2017-11-28 10:38:05 UTC
can't see any 'crash' here.
Comment 33 Francisco Cribari 2017-11-29 10:27:13 UTC
This is from dmesg (using the proposed firmware, I do not have a btmon log): 

[37289.795992] iwlwifi 0000:01:00.0: Queue 11 is active on fifo 1 and stuck for 10000 ms. SW [47, 78] HW [47, 78] FH TRB=0x0c010b03e                                                      
[37289.796208] iwlwifi 0000:01:00.0: Microcode SW error detected.  Restarting 0x2000000.     
[37289.796404] iwlwifi 0000:01:00.0: Start IWL Error Log Dump:                               
[37289.796419] iwlwifi 0000:01:00.0: Status: 0x00000100, count: 6                            
[37289.796429] iwlwifi 0000:01:00.0: Loaded firmware version: 31.622545.1                    
[37289.796441] iwlwifi 0000:01:00.0: 0x00000084 | NMI_INTERRUPT_UNKNOWN                      
[37289.796456] iwlwifi 0000:01:00.0: 0x000002F0 | trm_hw_status0                             
[37289.796471] iwlwifi 0000:01:00.0: 0x00000001 | trm_hw_status1                             
[37289.796482] iwlwifi 0000:01:00.0: 0x0001011C | branchlink2                                
[37289.796492] iwlwifi 0000:01:00.0: 0x00028EB2 | interruptlink1                             
[37289.796503] iwlwifi 0000:01:00.0: 0x00028EB2 | interruptlink2                             
[37289.796513] iwlwifi 0000:01:00.0: 0x00000000 | data1                                      
[37289.796524] iwlwifi 0000:01:00.0: 0x00000080 | data2                                      
[37289.796536] iwlwifi 0000:01:00.0: 0x07830000 | data3                                      
[37289.796550] iwlwifi 0000:01:00.0: 0x2B403C79 | beacon time                                
[37289.796565] iwlwifi 0000:01:00.0: 0xE6A5D385 | tsf low                                    
[37289.796575] iwlwifi 0000:01:00.0: 0x00000026 | tsf hi                                     
[37289.796589] iwlwifi 0000:01:00.0: 0x00000000 | time gp1                                   
[37289.796600] iwlwifi 0000:01:00.0: 0x017513E6 | time gp2                                   
[37289.796614] iwlwifi 0000:01:00.0: 0x00000001 | uCode revision type                        
[37289.796627] iwlwifi 0000:01:00.0: 0x0000001F | uCode version major                        
[37289.796639] iwlwifi 0000:01:00.0: 0x00097FD1 | uCode version minor                        
[37289.796655] iwlwifi 0000:01:00.0: 0x00000201 | hw version                                 
[37289.796666] iwlwifi 0000:01:00.0: 0x00C89008 | board version                              
[37289.796677] iwlwifi 0000:01:00.0: 0x00CE019C | hcmd                                       
[37289.796692] iwlwifi 0000:01:00.0: 0x0002200A | isr0                                       
[37289.796706] iwlwifi 0000:01:00.0: 0x00800000 | isr1                                       
[37289.796718] iwlwifi 0000:01:00.0: 0x0800180A | isr2                                       
[37289.796730] iwlwifi 0000:01:00.0: 0x004144C0 | isr3                                       
[37289.796743] iwlwifi 0000:01:00.0: 0x00000000 | isr4                                       
[37289.796754] iwlwifi 0000:01:00.0: 0x00CE019C | last cmd Id                                
[37289.796768] iwlwifi 0000:01:00.0: 0x00000000 | wait_event                                 
[37289.796780] iwlwifi 0000:01:00.0: 0x00007AC9 | l2p_control                                
[37289.796791] iwlwifi 0000:01:00.0: 0x00000020 | l2p_duration                               
[37289.796803] iwlwifi 0000:01:00.0: 0x00000003 | l2p_mhvalid                                
[37289.796816] iwlwifi 0000:01:00.0: 0x000000EE | l2p_addr_match                             
[37289.796829] iwlwifi 0000:01:00.0: 0x0000000D | lmpm_pmg_sel                               
[37289.796843] iwlwifi 0000:01:00.0: 0x14111330 | timestamp                                  
[37289.796859] iwlwifi 0000:01:00.0: 0x00346878 | flow_handler                               
[37289.796957] iwlwifi 0000:01:00.0: Start IWL Error Log Dump:                               
[37289.796972] iwlwifi 0000:01:00.0: Status: 0x00000100, count: 7                            
[37289.796985] iwlwifi 0000:01:00.0: 0x00000070 | ADVANCED_SYSASSERT                         
[37289.796997] iwlwifi 0000:01:00.0: 0x00000000 | umac branchlink1                           
[37289.797006] iwlwifi 0000:01:00.0: 0xC0086B6C | umac branchlink2                           
[37289.797015] iwlwifi 0000:01:00.0: 0xC00844E8 | umac interruptlink1                        
[37289.797023] iwlwifi 0000:01:00.0: 0xC00844E8 | umac interruptlink2                        
[37289.797033] iwlwifi 0000:01:00.0: 0x00000800 | umac data1                                 
[37289.797043] iwlwifi 0000:01:00.0: 0xC00844E8 | umac data2                                 
[37289.797051] iwlwifi 0000:01:00.0: 0xDEADBEEF | umac data3                                 
[37289.797059] iwlwifi 0000:01:00.0: 0x0000001F | umac major                                 
[37289.797068] iwlwifi 0000:01:00.0: 0x00097FD1 | umac minor                                 
[37289.797076] iwlwifi 0000:01:00.0: 0xC088628C | frame pointer                              
[37289.797085] iwlwifi 0000:01:00.0: 0xC088628C | stack pointer                              
[37289.797094] iwlwifi 0000:01:00.0: 0x00CE019C | last host cmd                              
[37289.797102] iwlwifi 0000:01:00.0: 0x00000000 | isr status reg                             
[37289.797118] ieee80211 phy0: Hardware restart was requested
[37315.182884] iwlwifi 0000:01:00.0: Queue 11 is active on fifo 1 and stuck for 10000 ms. SW [114, 214] HW [114, 214] FH TRB=0x0c010b081                                                  
[37315.183009] iwlwifi 0000:01:00.0: Microcode SW error detected.  Restarting 0x2000000.     
[37315.183172] iwlwifi 0000:01:00.0: Start IWL Error Log Dump:                               
[37315.183180] iwlwifi 0000:01:00.0: Status: 0x00000100, count: 6                            
[37315.183186] iwlwifi 0000:01:00.0: Loaded firmware version: 31.622545.1                    
[37315.183193] iwlwifi 0000:01:00.0: 0x00000084 | NMI_INTERRUPT_UNKNOWN                      
[37315.183200] iwlwifi 0000:01:00.0: 0x00000230 | trm_hw_status0                             
[37315.183205] iwlwifi 0000:01:00.0: 0x00000001 | trm_hw_status1                             
[37315.183211] iwlwifi 0000:01:00.0: 0x0001011C | branchlink2                                
[37315.183217] iwlwifi 0000:01:00.0: 0x00028EB2 | interruptlink1                             
[37315.183222] iwlwifi 0000:01:00.0: 0x00028EB2 | interruptlink2                             
[37315.183228] iwlwifi 0000:01:00.0: 0x00000000 | data1                                      
[37315.183233] iwlwifi 0000:01:00.0: 0x00000080 | data2                                      
[37315.183239] iwlwifi 0000:01:00.0: 0x07830000 | data3                                      
[37315.183244] iwlwifi 0000:01:00.0: 0x2B405D87 | beacon time                                
[37315.183250] iwlwifi 0000:01:00.0: 0xE8293278 | tsf low                                    
[37315.183256] iwlwifi 0000:01:00.0: 0x00000026 | tsf hi                                     
[37315.183261] iwlwifi 0000:01:00.0: 0x00000000 | time gp1                                   
[37315.183267] iwlwifi 0000:01:00.0: 0x0178313C | time gp2                                   
[37315.183272] iwlwifi 0000:01:00.0: 0x00000001 | uCode revision type                        
[37315.183278] iwlwifi 0000:01:00.0: 0x0000001F | uCode version major                        
[37315.183284] iwlwifi 0000:01:00.0: 0x00097FD1 | uCode version minor                        
[37315.183290] iwlwifi 0000:01:00.0: 0x00000201 | hw version                                 
[37315.183295] iwlwifi 0000:01:00.0: 0x00C89008 | board version                              
[37315.183301] iwlwifi 0000:01:00.0: 0x008C019C | hcmd                                       
[37315.183306] iwlwifi 0000:01:00.0: 0x2402200A | isr0                                       
[37315.183312] iwlwifi 0000:01:00.0: 0x00800000 | isr1                                       
[37315.183317] iwlwifi 0000:01:00.0: 0x0800180A | isr2                                       
[37315.183323] iwlwifi 0000:01:00.0: 0x004144C0 | isr3                                       
[37315.183328] iwlwifi 0000:01:00.0: 0x00000000 | isr4                                       
[37315.183333] iwlwifi 0000:01:00.0: 0x008C019C | last cmd Id                                
[37315.183338] iwlwifi 0000:01:00.0: 0x00000000 | wait_event                                 
[37315.183343] iwlwifi 0000:01:00.0: 0x000000D4 | l2p_control                                
[37315.183349] iwlwifi 0000:01:00.0: 0x00010030 | l2p_duration                               
[37315.183355] iwlwifi 0000:01:00.0: 0x00000007 | l2p_mhvalid                                
[37315.183361] iwlwifi 0000:01:00.0: 0x00000000 | l2p_addr_match                             
[37315.183367] iwlwifi 0000:01:00.0: 0x0000000D | lmpm_pmg_sel                               
[37315.183372] iwlwifi 0000:01:00.0: 0x14111330 | timestamp                                  
[37315.183378] iwlwifi 0000:01:00.0: 0x00348898 | flow_handler                               
[37315.183452] iwlwifi 0000:01:00.0: 0x00000000 | ADVANCED_SYSASSERT                         
[37315.183458] iwlwifi 0000:01:00.0: 0x00000000 | umac branchlink1                           
[37315.183464] iwlwifi 0000:01:00.0: 0x00000000 | umac branchlink2                           
[37315.183470] iwlwifi 0000:01:00.0: 0x00000000 | umac interruptlink1                        
[37315.183475] iwlwifi 0000:01:00.0: 0x00000000 | umac interruptlink2                        
[37315.183480] iwlwifi 0000:01:00.0: 0x00000000 | umac data1                                 
[37315.183485] iwlwifi 0000:01:00.0: 0x00000000 | umac data2                                 
[37315.183490] iwlwifi 0000:01:00.0: 0x00000000 | umac data3                                 
[37315.183495] iwlwifi 0000:01:00.0: 0x00000000 | umac major                                 
[37315.183501] iwlwifi 0000:01:00.0: 0x00000000 | umac minor                                 
[37315.183506] iwlwifi 0000:01:00.0: 0x00000000 | frame pointer                              
[37315.183512] iwlwifi 0000:01:00.0: 0x00000000 | stack pointer                              
[37315.183518] iwlwifi 0000:01:00.0: 0x00000000 | last host cmd                              
[37315.183523] iwlwifi 0000:01:00.0: 0x00000000 | isr status reg                             
[37315.183534] ieee80211 phy0: Hardware restart was requested
[37485.423046] iwlwifi 0000:01:00.0: Queue 11 is active on fifo 1 and stuck for 10000 ms. SW [148, 167] HW [148, 167] FH TRB=0x0c010b0a3                                                  
[37485.423189] iwlwifi 0000:01:00.0: Microcode SW error detected.  Restarting 0x2000000.     
[37485.423347] iwlwifi 0000:01:00.0: Start IWL Error Log Dump:                               
[37485.423354] iwlwifi 0000:01:00.0: Status: 0x00000100, count: 6                            
[37485.423360] iwlwifi 0000:01:00.0: Loaded firmware version: 31.622545.1                    
[37485.423367] iwlwifi 0000:01:00.0: 0x00000084 | NMI_INTERRUPT_UNKNOWN                      
[37485.423374] iwlwifi 0000:01:00.0: 0x00000230 | trm_hw_status0                             
[37485.423380] iwlwifi 0000:01:00.0: 0x00000001 | trm_hw_status1                             
[37485.423385] iwlwifi 0000:01:00.0: 0x0001011C | branchlink2                                
[37485.423391] iwlwifi 0000:01:00.0: 0x00028EB2 | interruptlink1                             
[37485.423396] iwlwifi 0000:01:00.0: 0x00028EB2 | interruptlink2                             
[37485.423401] iwlwifi 0000:01:00.0: 0x00000000 | data1                                      
[37485.423407] iwlwifi 0000:01:00.0: 0x00000080 | data2                                      
[37485.423412] iwlwifi 0000:01:00.0: 0x07830000 | data3                                      
[37485.423418] iwlwifi 0000:01:00.0: 0x8C41273C | beacon time                                
[37485.423423] iwlwifi 0000:01:00.0: 0xF24ED8C2 | tsf low                                    
[37485.423428] iwlwifi 0000:01:00.0: 0x00000026 | tsf hi                                     
[37485.423434] iwlwifi 0000:01:00.0: 0x00000000 | time gp1                                   
[37485.423440] iwlwifi 0000:01:00.0: 0x0A1A90B1 | time gp2                                   
[37485.423445] iwlwifi 0000:01:00.0: 0x00000001 | uCode revision type                        
[37485.423450] iwlwifi 0000:01:00.0: 0x0000001F | uCode version major                        
[37485.423456] iwlwifi 0000:01:00.0: 0x00097FD1 | uCode version minor                        
[37485.423461] iwlwifi 0000:01:00.0: 0x00000201 | hw version                                 
[37485.423467] iwlwifi 0000:01:00.0: 0x00C89008 | board version                              
[37485.423472] iwlwifi 0000:01:00.0: 0x0033019C | hcmd                                       
[37485.423478] iwlwifi 0000:01:00.0: 0x2402200A | isr0                                       
[37485.423483] iwlwifi 0000:01:00.0: 0x01800000 | isr1                                       
[37485.423488] iwlwifi 0000:01:00.0: 0x0800180A | isr2                                       
[37485.423493] iwlwifi 0000:01:00.0: 0x004144C0 | isr3                                       
[37485.423498] iwlwifi 0000:01:00.0: 0x00000000 | isr4                                       
[37485.423504] iwlwifi 0000:01:00.0: 0x0033019C | last cmd Id                                
[37485.423509] iwlwifi 0000:01:00.0: 0x00000000 | wait_event
[37485.423515] iwlwifi 0000:01:00.0: 0x00000080 | l2p_control
[37485.423520] iwlwifi 0000:01:00.0: 0x00010030 | l2p_duration
[37485.423526] iwlwifi 0000:01:00.0: 0x0000003F | l2p_mhvalid
[37485.423531] iwlwifi 0000:01:00.0: 0x000000CE | l2p_addr_match
[37485.423536] iwlwifi 0000:01:00.0: 0x0000000F | lmpm_pmg_sel
[37485.423542] iwlwifi 0000:01:00.0: 0x14111330 | timestamp
[37485.423547] iwlwifi 0000:01:00.0: 0x00348898 | flow_handler
[37485.423620] iwlwifi 0000:01:00.0: 0x00000000 | ADVANCED_SYSASSERT
[37485.423625] iwlwifi 0000:01:00.0: 0x00000000 | umac branchlink1
[37485.423631] iwlwifi 0000:01:00.0: 0x00000000 | umac branchlink2
[37485.423636] iwlwifi 0000:01:00.0: 0x00000000 | umac interruptlink1
[37485.423641] iwlwifi 0000:01:00.0: 0x00000000 | umac interruptlink2
[37485.423647] iwlwifi 0000:01:00.0: 0x00000000 | umac data1
[37485.423652] iwlwifi 0000:01:00.0: 0x00000000 | umac data2
[37485.423657] iwlwifi 0000:01:00.0: 0x00000000 | umac data3
[37485.423662] iwlwifi 0000:01:00.0: 0x00000000 | umac major
[37485.423667] iwlwifi 0000:01:00.0: 0x00000000 | umac minor
[37485.423672] iwlwifi 0000:01:00.0: 0x00000000 | frame pointer
[37485.423677] iwlwifi 0000:01:00.0: 0x00000000 | stack pointer
[37485.423683] iwlwifi 0000:01:00.0: 0x00000000 | last host cmd
[37485.423688] iwlwifi 0000:01:00.0: 0x00000000 | isr status reg
[37485.423698] ieee80211 phy0: Hardware restart was requested
Comment 34 Emmanuel Grumbach 2017-11-29 10:42:04 UTC
That's sad.

Happens only with BT?

What is the repro rate?

I'll need to send a wifi firmware with debug enabled.
Comment 35 Francisco Cribari 2017-11-29 10:44:36 UTC
I rebooted and it happened again. From dmesg: 

[  717.292717] iwlwifi 0000:01:00.0: Queue 5 is active on fifo 3 and stuck for 10000 ms. SW [84, 101] HW [84, 101] FH TRB=0x080305063                                                     
[  717.292840] iwlwifi 0000:01:00.0: Microcode SW error detected.  Restarting 0x2000000.     
[  717.293009] iwlwifi 0000:01:00.0: Start IWL Error Log Dump:                               
[  717.293020] iwlwifi 0000:01:00.0: Status: 0x00000100, count: 6                            
[  717.293030] iwlwifi 0000:01:00.0: Loaded firmware version: 31.622545.1                    
[  717.293041] iwlwifi 0000:01:00.0: 0x00000084 | NMI_INTERRUPT_UNKNOWN                      
[  717.293051] iwlwifi 0000:01:00.0: 0x000002B0 | trm_hw_status0                             
[  717.293060] iwlwifi 0000:01:00.0: 0x00000000 | trm_hw_status1                             
[  717.293069] iwlwifi 0000:01:00.0: 0x0001011C | branchlink2                                
[  717.293079] iwlwifi 0000:01:00.0: 0x00028EB2 | interruptlink1                             
[  717.293088] iwlwifi 0000:01:00.0: 0x000009B8 | interruptlink2                             
[  717.293096] iwlwifi 0000:01:00.0: 0x00000000 | data1                                      
[  717.293105] iwlwifi 0000:01:00.0: 0x00000080 | data2                                      
[  717.293114] iwlwifi 0000:01:00.0: 0x07830000 | data3                                      
[  717.293124] iwlwifi 0000:01:00.0: 0x058053BB | beacon time                                
[  717.293132] iwlwifi 0000:01:00.0: 0x3A264C43 | tsf low                                    
[  717.293141] iwlwifi 0000:01:00.0: 0x00000027 | tsf hi                                     
[  717.293150] iwlwifi 0000:01:00.0: 0x00000000 | time gp1                                   
[  717.293160] iwlwifi 0000:01:00.0: 0x0D0782FA | time gp2                                   
[  717.293169] iwlwifi 0000:01:00.0: 0x00000001 | uCode revision type                        
[  717.293179] iwlwifi 0000:01:00.0: 0x0000001F | uCode version major                        
[  717.293189] iwlwifi 0000:01:00.0: 0x00097FD1 | uCode version minor                        
[  717.293198] iwlwifi 0000:01:00.0: 0x00000201 | hw version                                 
[  717.293207] iwlwifi 0000:01:00.0: 0x00C89008 | board version                              
[  717.293217] iwlwifi 0000:01:00.0: 0x001A019C | hcmd                                       
[  717.293226] iwlwifi 0000:01:00.0: 0x0002200E | isr0                                       
[  717.293234] iwlwifi 0000:01:00.0: 0x00800000 | isr1                                       
[  717.293243] iwlwifi 0000:01:00.0: 0x0800180A | isr2                                       
[  717.293252] iwlwifi 0000:01:00.0: 0x004144C0 | isr3                                       
[  717.293261] iwlwifi 0000:01:00.0: 0x00000000 | isr4                                       
[  717.293271] iwlwifi 0000:01:00.0: 0x001A019C | last cmd Id                                
[  717.293280] iwlwifi 0000:01:00.0: 0x00000000 | wait_event                                 
[  717.293288] iwlwifi 0000:01:00.0: 0x00000080 | l2p_control                                
[  717.293297] iwlwifi 0000:01:00.0: 0x00010020 | l2p_duration
[  717.293306] iwlwifi 0000:01:00.0: 0x0000003F | l2p_mhvalid
[  717.293313] iwlwifi 0000:01:00.0: 0x000000CE | l2p_addr_match
[  717.293321] iwlwifi 0000:01:00.0: 0x0000000D | lmpm_pmg_sel
[  717.293329] iwlwifi 0000:01:00.0: 0x14111330 | timestamp
[  717.293339] iwlwifi 0000:01:00.0: 0x0034C0D0 | flow_handler
[  717.293416] iwlwifi 0000:01:00.0: Start IWL Error Log Dump:
[  717.293426] iwlwifi 0000:01:00.0: Status: 0x00000100, count: 7
[  717.293436] iwlwifi 0000:01:00.0: 0x00000070 | ADVANCED_SYSASSERT
[  717.293445] iwlwifi 0000:01:00.0: 0x00000000 | umac branchlink1
[  717.293453] iwlwifi 0000:01:00.0: 0xC0086B6C | umac branchlink2
[  717.293462] iwlwifi 0000:01:00.0: 0xC00844E8 | umac interruptlink1
[  717.293472] iwlwifi 0000:01:00.0: 0xC00844E8 | umac interruptlink2
[  717.293480] iwlwifi 0000:01:00.0: 0x00000800 | umac data1
[  717.293489] iwlwifi 0000:01:00.0: 0xC00844E8 | umac data2
[  717.293498] iwlwifi 0000:01:00.0: 0xDEADBEEF | umac data3
[  717.293507] iwlwifi 0000:01:00.0: 0x0000001F | umac major
[  717.293516] iwlwifi 0000:01:00.0: 0x00097FD1 | umac minor
[  717.293524] iwlwifi 0000:01:00.0: 0xC088628C | frame pointer
[  717.293532] iwlwifi 0000:01:00.0: 0xC088628C | stack pointer
[  717.293541] iwlwifi 0000:01:00.0: 0x001A019C | last host cmd
[  717.293550] iwlwifi 0000:01:00.0: 0x00000000 | isr status reg
[  717.293565] ieee80211 phy0: Hardware restart was requested
Comment 36 Emmanuel Grumbach 2017-11-29 10:45:55 UTC
yeah ok.

So, please go back to the regular WiFi firmware.
Comment 37 Francisco Cribari 2017-11-29 10:54:55 UTC
I reverted back to the regular wifi firmware (iwlwifi-8000C-31.ucode) and rebooted (BT coex on). This is from dmesg: 

[    3.124768] Bluetooth: Core ver 2.22
[    3.124805] NET: Registered protocol family 31
[    3.124805] Bluetooth: HCI device and connection manager initialized
[    3.124809] Bluetooth: HCI socket layer initialized
[    3.124811] Bluetooth: L2CAP socket layer initialized
[    3.124816] Bluetooth: SCO socket layer initialized
[    3.130695] usbcore: registered new interface driver btusb
[    3.132310] Bluetooth: hci0: Firmware revision 0.0 build 176 week 45 2017
[    3.132495] uvcvideo: Found UVC 1.00 device ATIV Real HD Camera (2232:1079)
[    3.135221] uvcvideo 1-6:1.0: Entity type for entity Extension 4 was not initialized!
[    3.135222] uvcvideo 1-6:1.0: Entity type for entity Processing 2 was not initialized!
[    3.135223] uvcvideo 1-6:1.0: Entity type for entity Camera 1 was not initialized!
[    3.135319] input: ATIV Real HD Camera: ATIV Real  as /devices/pci0000:00/0000:00:14.0/usb1/1-6/1-6:1.0/input/input19
[    3.135399] usbcore: registered new interface driver uvcvideo
[    3.135400] USB Video Class driver (1.1.1)
[    3.145366] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[    3.145367] Bluetooth: BNEP filters: protocol multicast
[    3.145370] Bluetooth: BNEP socket layer initialized
[    3.151497] IPv6: ADDRCONF(NETDEV_UP): wlp1s0: link is not ready
[    3.345503] Console: switching to colour frame buffer device 240x67
[    3.357258] [drm] RC6 off
[    3.383339] i915 0000:00:02.0: fb0: inteldrmfb frame buffer device
[    3.401967] IPv6: ADDRCONF(NETDEV_UP): wlp1s0: link is not ready
[    3.462658] IPv6: ADDRCONF(NETDEV_UP): wlp1s0: link is not ready
[   23.617111] IPv6: ADDRCONF(NETDEV_UP): wlp1s0: link is not ready
[   25.111989] Bluetooth: RFCOMM TTY layer initialized
[   25.111995] Bluetooth: RFCOMM socket layer initialized
[   25.111999] Bluetooth: RFCOMM ver 1.11
[   28.048354] fuse init (API version 7.26)
[   29.523363] NET: Registered protocol family 38
[   29.922720] input: Designer Mouse as /devices/virtual/misc/uhid/0005:045E:0805.0002/input/input20
[   29.923796] hid-generic 0005:045E:0805.0002: input,hidraw1: BLUETOOTH HID v1.00 Mouse [Designer Mouse] on 00:C2:C6:CF:A5:25
[   54.009110] IPv6: ADDRCONF(NETDEV_UP): wlp1s0: link is not ready
[   54.019098] IPv6: ADDRCONF(NETDEV_UP): wlp1s0: link is not ready
[   54.129397] IPv6: ADDRCONF(NETDEV_UP): wlp1s0: link is not ready
[   54.225785] wlp1s0: authenticate with c8:3a:35:11:c6:38
[   54.230889] wlp1s0: send auth to c8:3a:35:11:c6:38 (try 1/3)
[   54.239175] wlp1s0: authenticated
[   54.240022] wlp1s0: associate with c8:3a:35:11:c6:38 (try 1/3)
[   54.245285] wlp1s0: RX AssocResp from c8:3a:35:11:c6:38 (capab=0x411 status=0 aid=2)
[   54.254665] wlp1s0: associated
[   54.254705] IPv6: ADDRCONF(NETDEV_CHANGE): wlp1s0: link becomes ready
[  134.929262] wlp1s0: deauthenticating from c8:3a:35:11:c6:38 by local choice (Reason: 3=DEAUTH_LEAVING)
[  134.971752] wlp1s0: failed to remove key (1, ff:ff:ff:ff:ff:ff) from hardware (-22)
[  134.987257] IPv6: ADDRCONF(NETDEV_UP): wlp1s0: link is not ready
[  135.142749] IPv6: ADDRCONF(NETDEV_UP): wlp1s0: link is not ready
[  138.051711] wlp1s0: authenticate with 10:be:f5:d8:7c:9c
[  138.060863] wlp1s0: send auth to 10:be:f5:d8:7c:9c (try 1/3)
[  138.067408] wlp1s0: authenticated
[  138.070551] wlp1s0: associate with 10:be:f5:d8:7c:9c (try 1/3)
[  138.074584] wlp1s0: RX AssocResp from 10:be:f5:d8:7c:9c (capab=0x411 status=0 aid=3)
[  138.077864] wlp1s0: associated
[  138.078166] IPv6: ADDRCONF(NETDEV_CHANGE): wlp1s0: link becomes ready
[  152.796752] iwlwifi 0000:01:00.0: Queue 11 is active on fifo 1 and stuck for 10000 ms. SW [53, 98] HW [53, 98] FH TRB=0x0c010b044                                                      
[  152.796760] iwlwifi 0000:01:00.0: Queue 5 is active on fifo 3 and stuck for 10000 ms. SW [33, 74] HW [33, 74] FH TRB=0x08030502f                                                       
[  152.796906] iwlwifi 0000:01:00.0: Microcode SW error detected.  Restarting 0x2000000.     
[  152.797070] iwlwifi 0000:01:00.0: Start IWL Error Log Dump:                               
[  152.797078] iwlwifi 0000:01:00.0: Status: 0x00000100, count: 6                            
[  152.797084] iwlwifi 0000:01:00.0: Loaded firmware version: 31.532993.0                    
[  152.797091] iwlwifi 0000:01:00.0: 0x00000084 | NMI_INTERRUPT_UNKNOWN                      
[  152.797098] iwlwifi 0000:01:00.0: 0x00000230 | trm_hw_status0                             
[  152.797103] iwlwifi 0000:01:00.0: 0x00000001 | trm_hw_status1                             
[  152.797109] iwlwifi 0000:01:00.0: 0x00010040 | branchlink2                                
[  152.797115] iwlwifi 0000:01:00.0: 0x00028DA6 | interruptlink1                             
[  152.797120] iwlwifi 0000:01:00.0: 0x00028DA6 | interruptlink2                             
[  152.797125] iwlwifi 0000:01:00.0: 0x00000000 | data1                                      
[  152.797130] iwlwifi 0000:01:00.0: 0x00000080 | data2                                      
[  152.797136] iwlwifi 0000:01:00.0: 0x07830000 | data3                                      
[  152.797141] iwlwifi 0000:01:00.0: 0x2400EDD3 | beacon time                                
[  152.797146] iwlwifi 0000:01:00.0: 0x5C15322B | tsf low                                    
[  152.797152] iwlwifi 0000:01:00.0: 0x00000027 | tsf hi                                     
[  152.797157] iwlwifi 0000:01:00.0: 0x00000000 | time gp1                                   
[  152.797163] iwlwifi 0000:01:00.0: 0x08E813E1 | time gp2                                   
[  152.797168] iwlwifi 0000:01:00.0: 0x00000001 | uCode revision type                        
[  152.797173] iwlwifi 0000:01:00.0: 0x0000001F | uCode version major                        
[  152.797179] iwlwifi 0000:01:00.0: 0x00082201 | uCode version minor                        
[  152.797184] iwlwifi 0000:01:00.0: 0x00000201 | hw version                                 
[  152.797190] iwlwifi 0000:01:00.0: 0x00C89008 | board version                              
[  152.797195] iwlwifi 0000:01:00.0: 0x00DF019C | hcmd                                       
[  152.797201] iwlwifi 0000:01:00.0: 0x2402200E | isr0                                       
[  152.797206] iwlwifi 0000:01:00.0: 0x00800000 | isr1                                       
[  152.797211] iwlwifi 0000:01:00.0: 0x0800180B | isr2                                       
[  152.797216] iwlwifi 0000:01:00.0: 0x004144C0 | isr3                                       
[  152.797221] iwlwifi 0000:01:00.0: 0x00000000 | isr4                                       
[  152.797226] iwlwifi 0000:01:00.0: 0x00DF019C | last cmd Id                                
[  152.797232] iwlwifi 0000:01:00.0: 0x00000000 | wait_event                                 
[  152.797237] iwlwifi 0000:01:00.0: 0x00000080 | l2p_control                                
[  152.797242] iwlwifi 0000:01:00.0: 0x00010030 | l2p_duration                               
[  152.797248] iwlwifi 0000:01:00.0: 0x0000003F | l2p_mhvalid                                
[  152.797253] iwlwifi 0000:01:00.0: 0x00000080 | l2p_addr_match                             
[  152.797258] iwlwifi 0000:01:00.0: 0x0000000F | lmpm_pmg_sel                               
[  152.797264] iwlwifi 0000:01:00.0: 0x15062149 | timestamp                                  
[  152.797269] iwlwifi 0000:01:00.0: 0x0034E0F0 | flow_handler                               
[  152.797341] iwlwifi 0000:01:00.0: 0x00000000 | ADVANCED_SYSASSERT                         
[  152.797347] iwlwifi 0000:01:00.0: 0x00000000 | umac branchlink1                           
[  152.797352] iwlwifi 0000:01:00.0: 0x00000000 | umac branchlink2                           
[  152.797357] iwlwifi 0000:01:00.0: 0x00000000 | umac interruptlink1                        
[  152.797362] iwlwifi 0000:01:00.0: 0x00000000 | umac interruptlink2                        
[  152.797368] iwlwifi 0000:01:00.0: 0x00000000 | umac data1                                 
[  152.797372] iwlwifi 0000:01:00.0: 0x00000000 | umac data2                                 
[  152.797377] iwlwifi 0000:01:00.0: 0x00000000 | umac data3                                 
[  152.797383] iwlwifi 0000:01:00.0: 0x00000000 | umac major                                 
[  152.797388] iwlwifi 0000:01:00.0: 0x00000000 | umac minor                                 
[  152.797393] iwlwifi 0000:01:00.0: 0x00000000 | frame pointer                              
[  152.797398] iwlwifi 0000:01:00.0: 0x00000000 | stack pointer                              
[  152.797403] iwlwifi 0000:01:00.0: 0x00000000 | last host cmd                              
[  152.797408] iwlwifi 0000:01:00.0: 0x00000000 | isr status reg                             
[  152.797419] ieee80211 phy0: Hardware restart was requested
[  167.303313] iwlwifi 0000:01:00.0: Queue 5 is active on fifo 3 and stuck for 10000 ms. SW [21, 63] HW [21, 63] FH TRB=0x080305024                                                       
[  167.303404] iwlwifi 0000:01:00.0: Queue 11 is active on fifo 1 and stuck for 10000 ms. SW [100, 187] HW [100, 187] FH TRB=0x0c010b073                                                  
[  167.303436] iwlwifi 0000:01:00.0: Microcode SW error detected.  Restarting 0x2000000.     
[  167.303577] iwlwifi 0000:01:00.0: Start IWL Error Log Dump:                               
[  167.303582] iwlwifi 0000:01:00.0: Status: 0x00000100, count: 6                            
[  167.303587] iwlwifi 0000:01:00.0: Loaded firmware version: 31.532993.0                    
[  167.303593] iwlwifi 0000:01:00.0: 0x00000084 | NMI_INTERRUPT_UNKNOWN                      
[  167.303598] iwlwifi 0000:01:00.0: 0x00000230 | trm_hw_status0                             
[  167.303603] iwlwifi 0000:01:00.0: 0x00000001 | trm_hw_status1                             
[  167.303607] iwlwifi 0000:01:00.0: 0x00010040 | branchlink2                                
[  167.303610] iwlwifi 0000:01:00.0: 0x00028DA6 | interruptlink1                             
[  167.303615] iwlwifi 0000:01:00.0: 0x00028DA6 | interruptlink2                             
[  167.303620] iwlwifi 0000:01:00.0: 0x00000000 | data1                                      
[  167.303624] iwlwifi 0000:01:00.0: 0x00000080 | data2                                      
[  167.303627] iwlwifi 0000:01:00.0: 0x07830000 | data3                                      
[  167.303630] iwlwifi 0000:01:00.0: 0x114173BA | beacon time                                
[  167.303633] iwlwifi 0000:01:00.0: 0x5CF28C43 | tsf low                                    
[  167.303636] iwlwifi 0000:01:00.0: 0x00000027 | tsf hi                                     
[  167.303639] iwlwifi 0000:01:00.0: 0x00000000 | time gp1                                   
[  167.303642] iwlwifi 0000:01:00.0: 0x00D268F3 | time gp2                                   
[  167.303645] iwlwifi 0000:01:00.0: 0x00000001 | uCode revision type                        
[  167.303648] iwlwifi 0000:01:00.0: 0x0000001F | uCode version major                        
[  167.303652] iwlwifi 0000:01:00.0: 0x00082201 | uCode version minor                        
[  167.303655] iwlwifi 0000:01:00.0: 0x00000201 | hw version                                 
[  167.303658] iwlwifi 0000:01:00.0: 0x00C89008 | board version                              
[  167.303661] iwlwifi 0000:01:00.0: 0x0083019C | hcmd                                       
[  167.303664] iwlwifi 0000:01:00.0: 0x2402200A | isr0                                       
[  167.303667] iwlwifi 0000:01:00.0: 0x01800000 | isr1                                       
[  167.303670] iwlwifi 0000:01:00.0: 0x0800180A | isr2                                       
[  167.303672] iwlwifi 0000:01:00.0: 0x004144C0 | isr3                                       
[  167.303675] iwlwifi 0000:01:00.0: 0x00000000 | isr4                                       
[  167.303678] iwlwifi 0000:01:00.0: 0x0083019C | last cmd Id                                
[  167.303681] iwlwifi 0000:01:00.0: 0x00000000 | wait_event
[  167.303684] iwlwifi 0000:01:00.0: 0x00000080 | l2p_control
[  167.303687] iwlwifi 0000:01:00.0: 0x00010030 | l2p_duration
[  167.303690] iwlwifi 0000:01:00.0: 0x0000003F | l2p_mhvalid
[  167.303693] iwlwifi 0000:01:00.0: 0x000000CE | l2p_addr_match
[  167.303696] iwlwifi 0000:01:00.0: 0x0000000F | lmpm_pmg_sel
[  167.303699] iwlwifi 0000:01:00.0: 0x15062149 | timestamp
[  167.303702] iwlwifi 0000:01:00.0: 0x00347890 | flow_handler
[  167.303772] iwlwifi 0000:01:00.0: 0x00000000 | ADVANCED_SYSASSERT
[  167.303776] iwlwifi 0000:01:00.0: 0x00000000 | umac branchlink1
[  167.303779] iwlwifi 0000:01:00.0: 0x00000000 | umac branchlink2
[  167.303782] iwlwifi 0000:01:00.0: 0x00000000 | umac interruptlink1
[  167.303785] iwlwifi 0000:01:00.0: 0x00000000 | umac interruptlink2
[  167.303788] iwlwifi 0000:01:00.0: 0x00000000 | umac data1
[  167.303790] iwlwifi 0000:01:00.0: 0x00000000 | umac data2
[  167.303793] iwlwifi 0000:01:00.0: 0x00000000 | umac data3
[  167.303796] iwlwifi 0000:01:00.0: 0x00000000 | umac major
[  167.303799] iwlwifi 0000:01:00.0: 0x00000000 | umac minor
[  167.303802] iwlwifi 0000:01:00.0: 0x00000000 | frame pointer
[  167.303806] iwlwifi 0000:01:00.0: 0x00000000 | stack pointer
[  167.303808] iwlwifi 0000:01:00.0: 0x00000000 | last host cmd
[  167.303812] iwlwifi 0000:01:00.0: 0x00000000 | isr status reg
[  167.303819] ieee80211 phy0: Hardware restart was requested
Comment 38 Francisco Cribari 2017-11-29 16:03:20 UTC
I reverted all firmware changes (sudo pacman -S linux-firmware) and the errors remained. However, they do not show up when I disable BT coexistence. With BT coex off what I see in dmesg is: 

[   43.526706] IPv6: ADDRCONF(NETDEV_CHANGE): wlp1s0: link becomes ready
[  206.100007] wlp1s0: deauthenticating from 10:be:f5:d8:7c:9e by local choice (Reason: 3=DEAUTH_LEAVING)
[  206.108400] wlp1s0: failed to remove key (1, ff:ff:ff:ff:ff:ff) from hardware (-22)
[  206.119405] IPv6: ADDRCONF(NETDEV_UP): wlp1s0: link is not ready
[  206.210387] IPv6: ADDRCONF(NETDEV_UP): wlp1s0: link is not ready
[  206.259793] wlp1s0: authenticate with 10:be:f5:d8:7c:9c
[  206.263934] wlp1s0: send auth to 10:be:f5:d8:7c:9c (try 1/3)
[  206.271015] wlp1s0: authenticated
[  206.272680] wlp1s0: associate with 10:be:f5:d8:7c:9c (try 1/3)
[  206.276671] wlp1s0: RX AssocResp from 10:be:f5:d8:7c:9c (capab=0x411 status=0 aid=1)
[  206.284406] wlp1s0: associated
[  206.284446] IPv6: ADDRCONF(NETDEV_CHANGE): wlp1s0: link becomes ready
Comment 39 Francisco Cribari 2017-11-29 20:56:06 UTC
Well, even w/ BT coex off, I saw these error messages in dmesg: 

[ 6841.697820] PM: suspend exit
[ 6841.704052] IPv6: ADDRCONF(NETDEV_UP): enp2s0: link is not ready
[ 6841.704392] enp2s0: 0xffffba5101006000, 98:83:89:6c:49:7a, IRQ 125
[ 6841.759237] IPv6: ADDRCONF(NETDEV_UP): enp2s0: link is not ready
[ 6841.760200] IPv6: ADDRCONF(NETDEV_UP): wlp1s0: link is not ready
[ 6841.992842] IPv6: ADDRCONF(NETDEV_UP): wlp1s0: link is not ready
[ 6842.240575] IPv6: ADDRCONF(NETDEV_UP): wlp1s0: link is not ready
[ 6842.766450] IPv6: ADDRCONF(NETDEV_UP): wlp1s0: link is not ready
[ 6846.081586] IPv6: ADDRCONF(NETDEV_UP): wlp1s0: link is not ready
[ 6848.043143] wlp1s0: authenticate with 70:3a:cb:29:33:a3
[ 6848.048866] wlp1s0: send auth to 70:3a:cb:29:33:a3 (try 1/3)
[ 6848.055840] wlp1s0: authenticated
[ 6848.058323] wlp1s0: associate with 70:3a:cb:29:33:a3 (try 1/3)
[ 6848.062509] wlp1s0: RX AssocResp from 70:3a:cb:29:33:a3 (capab=0x11 status=0 aid=1)
[ 6848.064233] wlp1s0: associated
[ 6848.064289] IPv6: ADDRCONF(NETDEV_CHANGE): wlp1s0: link becomes ready
[ 6969.223128] iwlwifi 0000:01:00.0: Queue 11 is active on fifo 1 and stuck for 10000 ms. SW [98, 148] HW [98, 148] FH TRB=0x0c010b071                                                    
[ 6969.223240] iwlwifi 0000:01:00.0: Microcode SW error detected.  Restarting 0x2000000.     
[ 6969.223399] iwlwifi 0000:01:00.0: Start IWL Error Log Dump:                               
[ 6969.223406] iwlwifi 0000:01:00.0: Status: 0x00000100, count: 6                            
[ 6969.223412] iwlwifi 0000:01:00.0: Loaded firmware version: 31.532993.0                    
[ 6969.223420] iwlwifi 0000:01:00.0: 0x00000084 | NMI_INTERRUPT_UNKNOWN                      
[ 6969.223426] iwlwifi 0000:01:00.0: 0x00000230 | trm_hw_status0                             
[ 6969.223432] iwlwifi 0000:01:00.0: 0x00000000 | trm_hw_status1                             
[ 6969.223437] iwlwifi 0000:01:00.0: 0x00010040 | branchlink2                                
[ 6969.223442] iwlwifi 0000:01:00.0: 0x00028DA6 | interruptlink1                             
[ 6969.223448] iwlwifi 0000:01:00.0: 0x00000986 | interruptlink2                             
[ 6969.223453] iwlwifi 0000:01:00.0: 0x00000000 | data1                                      
[ 6969.223458] iwlwifi 0000:01:00.0: 0x00000080 | data2                                      
[ 6969.223463] iwlwifi 0000:01:00.0: 0x07830000 | data3                                      
[ 6969.223469] iwlwifi 0000:01:00.0: 0x27C0E7D0 | beacon time                                
[ 6969.223474] iwlwifi 0000:01:00.0: 0x33FAB7FE | tsf low                                    
[ 6969.223479] iwlwifi 0000:01:00.0: 0x000000B2 | tsf hi                                     
[ 6969.223485] iwlwifi 0000:01:00.0: 0x00000000 | time gp1                                   
[ 6969.223490] iwlwifi 0000:01:00.0: 0x07921123 | time gp2                                   
[ 6969.223495] iwlwifi 0000:01:00.0: 0x00000001 | uCode revision type                        
[ 6969.223501] iwlwifi 0000:01:00.0: 0x0000001F | uCode version major                        
[ 6969.223506] iwlwifi 0000:01:00.0: 0x00082201 | uCode version minor                        
[ 6969.223512] iwlwifi 0000:01:00.0: 0x00000201 | hw version                                 
[ 6969.223517] iwlwifi 0000:01:00.0: 0x00C89008 | board version                              
[ 6969.223523] iwlwifi 0000:01:00.0: 0x002D019C | hcmd                                       
[ 6969.223528] iwlwifi 0000:01:00.0: 0x24022002 | isr0                                       
[ 6969.223533] iwlwifi 0000:01:00.0: 0x00800000 | isr1                                       
[ 6969.223539] iwlwifi 0000:01:00.0: 0x0800180A | isr2                                       
[ 6969.223544] iwlwifi 0000:01:00.0: 0x004144C0 | isr3                                       
[ 6969.223549] iwlwifi 0000:01:00.0: 0x00000000 | isr4                                       
[ 6969.223554] iwlwifi 0000:01:00.0: 0x002D019C | last cmd Id                                
[ 6969.223559] iwlwifi 0000:01:00.0: 0x00000000 | wait_event                                 
[ 6969.223565] iwlwifi 0000:01:00.0: 0x00000080 | l2p_control                                
[ 6969.223570] iwlwifi 0000:01:00.0: 0x00010030 | l2p_duration                               
[ 6969.223575] iwlwifi 0000:01:00.0: 0x0000003F | l2p_mhvalid                                
[ 6969.223581] iwlwifi 0000:01:00.0: 0x00000080 | l2p_addr_match                             
[ 6969.223586] iwlwifi 0000:01:00.0: 0x0000000D | lmpm_pmg_sel                               
[ 6969.223592] iwlwifi 0000:01:00.0: 0x15062149 | timestamp                                  
[ 6969.223597] iwlwifi 0000:01:00.0: 0x0034D0E0 | flow_handler                               
[ 6969.223671] iwlwifi 0000:01:00.0: 0x00000000 | ADVANCED_SYSASSERT                         
[ 6969.223676] iwlwifi 0000:01:00.0: 0x00000000 | umac branchlink1
[ 6969.223681] iwlwifi 0000:01:00.0: 0x00000000 | umac branchlink2
[ 6969.223687] iwlwifi 0000:01:00.0: 0x00000000 | umac interruptlink1
[ 6969.223692] iwlwifi 0000:01:00.0: 0x00000000 | umac interruptlink2
[ 6969.223697] iwlwifi 0000:01:00.0: 0x00000000 | umac data1
[ 6969.223702] iwlwifi 0000:01:00.0: 0x00000000 | umac data2
[ 6969.223707] iwlwifi 0000:01:00.0: 0x00000000 | umac data3
[ 6969.223712] iwlwifi 0000:01:00.0: 0x00000000 | umac major
[ 6969.223717] iwlwifi 0000:01:00.0: 0x00000000 | umac minor
[ 6969.223722] iwlwifi 0000:01:00.0: 0x00000000 | frame pointer
[ 6969.223728] iwlwifi 0000:01:00.0: 0x00000000 | stack pointer
[ 6969.223733] iwlwifi 0000:01:00.0: 0x00000000 | last host cmd
[ 6969.223738] iwlwifi 0000:01:00.0: 0x00000000 | isr status reg
[ 6969.223749] ieee80211 phy0: Hardware restart was requested
[ 6994.869688] usb 1-1: new high-speed USB device number 6 using xhci_hcd
Comment 40 Emmanuel Grumbach 2017-12-03 14:01:17 UTC
Created attachment 261007 [details]
latest Core28 with debug

Hi,

please record a firmware dump with this firmware.

Thank you.

Same instructions as in Comment 11 and same note about privacy.

Thank you.
Comment 41 Francisco Cribari 2017-12-03 15:22:38 UTC
@Emmanuel Grumbach Here it is. 1) dmesg dump is available at 

https://pastebin.com/quFBVZak

2) Firmware dump (Intel 8260, BT coex on) is available at

https://www.dropbox.com/s/sn2bi6bakii4rc0/iwl-fw-error_2017-12-03_12-16-17.dump?dl=0

The kernel I was using during the FW crash: 

[cribari@darwin5 ~]$ uname -a 
Linux darwin5 4.14.3-1-MANJARO #1 SMP PREEMPT Thu Nov 30 14:22:30 UTC 2017 x86_64 GNU/Linux
Comment 42 Emmanuel Grumbach 2017-12-03 18:09:48 UTC
Created attachment 261011 [details]
latest Core28 with debug

Sorry, but I need a bit more data.
I reduced the timeout in the firmware attached.
Please keep tracing running and when the problem reproduces, please stop the tracing.

Thanks.
Comment 43 Francisco Cribari 2017-12-03 18:33:58 UTC
Emmanuel Grumbach You write: "when the problem reproduces, please stop the tracing." How do I stop the tracing? The dump file is being created by the udev rule.
Comment 44 Emmanuel Grumbach 2017-12-03 18:36:34 UTC
Ok, I wasn't precise enough.

I meant this:
https://wireless.wiki.kernel.org/en/users/drivers/iwlwifi/debugging#tracing


This is a user space process that records all the driver interactions. When the firmware crashes, you can just stop this user space process by hitting CTRL+C.
After CTRL+C, it'll collect all the data in one file (can take a few seconds), and then you'll have a trace.data file. You can compress this file and attach it here / dropbox / whatever.

Thanks!
Comment 45 Emmanuel Grumbach 2017-12-04 06:41:29 UTC
If you can, it'll be nice to check what happens with -34.ucode.
-31.ucode will be EOL'ed very soon and maybe we should just jump to -34.ucode for the debugging.

In order to make -34.ucode, you'll need to jump to 4.14.3.

Thank you.
Comment 46 Francisco Cribari 2017-12-04 10:19:49 UTC
@Emmanuel Grumbach 1) I am running the latest testing firmware (comment 44) but so far a crash hasn't happened, 2) I am running kernel 4.14.3, but I don't have firmware 34. This is what I have in /lib/firmware: 

[cribari@darwin5 firmware]$ ls *8000C*.ucode
iwlwifi-8000C-13.ucode  iwlwifi-8000C-21.ucode  iwlwifi-8000C-27.ucode
iwlwifi-8000C-16.ucode  iwlwifi-8000C-22.ucode  iwlwifi-8000C-31.ucode

The version of linux-firmware available in the Manjaro repositories is 20171009.bf04291-1. This is what I have installed on my system.
Comment 48 Francisco Cribari 2017-12-04 11:16:58 UTC
@Emmanuel Grumbach A crash has just taken place (firmware -31.ucode, BT coex on, kernel 4.14.3). The dmesg dump is available at 

https://pastebin.com/hS3c9sLt

The firmware dump is available at 

https://www.dropbox.com/s/m2xwpm4aill3id5/iwl-fw-error_2017-12-04_07-45-32.dump?dl=0

The trace data is available at 

https://www.dropbox.com/s/378qi2jesk4evlu/trace.dat?dl=0

(This last file is quite large! Please, let me know when I can delete it from my Dropbox.). P.S. I downloaded the -34.ucode firmware using the link in Comment 47 file but I noticed that it is much larger than the other files (16 MB). Is that correct?
Comment 49 Emmanuel Grumbach 2017-12-04 11:25:16 UTC
16MB is way too big :)

You should download this link: https://git.kernel.org/pub/scm/linux/kernel/git/iwlwifi/linux-firmware.git/plain/iwlwifi-8000C-34.ucode

I was sending you to a webpage :)

Just FYI, both the trace of the dump file compress very well. You can use any compression you like, they'll shrink considerably.
I have downloaded them.
Comment 50 Francisco Cribari 2017-12-04 22:50:48 UTC
With the -34.ucode firmware I had this in dmesg: 

[   10.335401] IPv6: ADDRCONF(NETDEV_CHANGE): wlp1s0: link becomes ready
[   14.130854] fuse init (API version 7.26)
[   14.770140] Bluetooth: hci0: Failed to send Intel_Write_DDC (-110)
[   16.906671] Bluetooth: hci0 command 0xfc52 tx timeout
[   24.796650] Bluetooth: hci0: Setting Intel event mask failed (-110)
[   24.959035] Bluetooth: RFCOMM TTY layer initialized
[   24.959041] Bluetooth: RFCOMM socket layer initialized
[   24.959049] Bluetooth: RFCOMM ver 1.11
[   31.585081] Bluetooth: HIDP (Human Interface Emulation) ver 1.2
[   31.585087] Bluetooth: HIDP socket layer initialized
[   31.590644] hid-generic 0005:046D:B00D.0002: unknown main item tag 0x0
[   31.590885] input: Ultrathin Touch Mouse as /devices/pci0000:00/0000:00:14.0/usb1/1-5/1-5:1.0/bluetooth/hci0/hci0:256/0005:046D:B00D.0002/input/input20
[   31.591489] hid-generic 0005:046D:B00D.0002: input,hidraw1: BLUETOOTH HID v7.00 Keyboard [Ultrathin Touch Mouse] on 00:c2:c6:cf:a5:25
Comment 51 Emmanuel Grumbach 2017-12-05 04:12:26 UTC
Hm... So BT problems again...
Comment 52 Emmanuel Grumbach 2017-12-11 19:42:57 UTC
Hi,

I analyzed the data and forwarded it to the firmware team.
I did find something, this seems to be related to changes in the power definitions.

I can see that you tried to set the power save with iw exactly one second before the crash which matches exactly with the timeout I set in this debug firmware.
At some point, our firmware gets confused.
Comment 53 Francisco Cribari 2017-12-11 20:19:23 UTC
@Emmanuel Grumbach You write: "I can see that you tried to set the power save with iw exactly one second before the crash". I made no changes to my settings, including to power saving. I can assure you that. I just booted the machine and used it as I normally do until the crash happened.
Comment 54 Emmanuel Grumbach 2017-12-11 20:32:56 UTC
 iw-901   [002] 16093.362208: rdev_set_power_mgmt:  phy0, netdev:wlp1s0(3), enabled, timeout: -1 


So someone invoked iw... Very strange.

Doesn't matter, this can be a hint on how to reproduce the bug faster.
I wrapped up all the data for the firmware team to analyze. I'll keep you posted.
Comment 55 Francisco Cribari 2017-12-11 20:36:15 UTC
@Emmanuel Grumbach You write: "So someone invoked iw... Very strange." Indeed. The machine is a notebook (laptop) and I am the only user (besides root). If that happened, it wasn't by my intent. Perhaps Manjaro or KDE Plasma did something on their own...
Comment 56 Emmanuel Grumbach 2017-12-11 20:38:22 UTC
Might be.
Maybe they track the ACPI event of plug unplug the power cord.
It is not a very good idea because the NetworkManager wants to control this as well, but it doesn't matter at this stage.
Comment 57 Emmanuel Grumbach 2017-12-27 11:29:16 UTC
Hi Florian,

I am sending a newer firmware to you via email.

Please use it with our backport based driver or with kernel 4.15.
Our backport tree is here:

https://git.kernel.org/pub/scm/linux/kernel/git/iwlwifi/backport-iwlwifi.git/


The firmware team has made significant changes in this area and would like to know whether you still see the bug on that newer firmware.

Thank you.
Comment 58 Emmanuel Grumbach 2017-12-27 15:07:13 UTC
Sorry, I got confused, I meant:

Hi Francisco :)
Comment 59 Francisco Cribari 2017-12-27 21:50:23 UTC
@Emmanuel Grumbach Due to some other errors I was getting, I am no longer running Manjaro Linux on that laptop. It now runs Arch Linux. Manjaro is based on Arch, but they are not not identical. Since I migrated to Arch I haven't seen any assert errors in the logs. I've used the machine with and without BT coex, and with the both stock Arch kernel and the zen kernel. So far, no assert errors.
Comment 60 Emmanuel Grumbach 2017-12-28 06:23:57 UTC
All right. Closing the bug then.