Bug 205127

Summary: iwlwifi reports SW error on Intel 6250
Product: Networking Reporter: Dmitry (dma_k)
Component: WirelessAssignee: networking_wireless (networking_wireless)
Status: NEW ---    
Severity: normal CC: pedretti.fabio
Priority: P1    
Hardware: All   
OS: Linux   
Kernel Version: 4.19.0-6-amd64 Subsystem:
Regression: No Bisected commit-id:

Description Dmitry 2019-10-08 17:00:35 UTC 
I have Intel 6250 mPCI card which I would like to use in AP mode via hostapd. However the card does not work properly: once I try to connect to WiFi network, iwlwifi reports SW error and the client cannot establish the connection.

I have checked that my firmware is the latest one as to [1]. I tried to locate 6050 debug firmware in [2], but could not find one (please provide a link where can I download it). Without it I believe I cannot do

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

I have configured the modules as following trying to solve the issue by looking at examples in [3], [4], [5], [6] but with no success (WiFi card still does not work):

/etc/modprobe.d/cfg80211.conf:

options cfg80211 cfg80211_disable_40mhz_24ghz=Y

/etc/modprobe.d/iwlwifi.conf:

options iwlwifi swcrypto=1 11n_disable=8 bt_coex_active=0 power_save=0

Additional info:

# cat "/boot/config-`uname -r`" | grep COREDUMP
CONFIG_COREDUMP=y
CONFIG_WANT_DEV_COREDUMP=y
CONFIG_ALLOW_DEV_COREDUMP=y
CONFIG_DEV_COREDUMP=y

# ls /sys/devices/virtual/
bdi  dmi  graphics  input  mem  misc  net  powercap  sound  thermal  tty  vc  vtconsole  workqueue

Firmware file: iwlwifi-6050-5.ucode
Firmware: 41.28.5.1 build 33926

dmesg | egrep '(iwl|iee|6050)':
[Tue Oct  8 11:14:12 2019] iwlwifi 0000:01:00.0: can't disable ASPM; OS doesn't have ASPM control
[Tue Oct  8 11:14:12 2019] iwlwifi 0000:01:00.0: firmware: direct-loading firmware iwlwifi-6050-5.ucode
[Tue Oct  8 11:14:12 2019] iwlwifi 0000:01:00.0: loaded firmware version 41.28.5.1 build 33926 op_mode iwldvm
[Tue Oct  8 11:14:12 2019] iwlwifi 0000:01:00.0: CONFIG_IWLWIFI_DEBUG disabled
[Tue Oct  8 11:14:12 2019] iwlwifi 0000:01:00.0: CONFIG_IWLWIFI_DEBUGFS disabled
[Tue Oct  8 11:14:12 2019] iwlwifi 0000:01:00.0: CONFIG_IWLWIFI_DEVICE_TRACING disabled
[Tue Oct  8 11:14:12 2019] iwlwifi 0000:01:00.0: Detected Intel(R) Centrino(R) Advanced-N + WiMAX 6250 AGN, REV=0x84
[Tue Oct  8 11:14:12 2019] ieee80211 phy0: Selected rate control algorithm 'iwl-agn-rs'
[Tue Oct  8 11:14:14 2019] i2400m_usb 2-7.2:1.0: firmware: direct-loading firmware i6050-fw-usb-1.5.sbcf
[Tue Oct  8 11:14:19 2019] iwlwifi 0000:01:00.0: Radio type=0x1-0x2-0x0
[Tue Oct  8 11:14:19 2019] iwlwifi 0000:01:00.0: Radio type=0x1-0x2-0x0
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: Microcode SW error detected.  Restarting 0x2000000.
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: Loaded firmware version: 41.28.5.1 build 33926
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: Start IWL Error Log Dump:
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: Status: 0x000002CC, count: 5
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: 0x00000005 | SYSASSERT                   
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: 0x00024174 | uPc
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: 0x000240D6 | branchlink1
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: 0x000240D6 | branchlink2
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: 0x00001C16 | interruptlink1
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: 0x00000000 | interruptlink2
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: 0x00000258 | data1
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: 0x000000C8 | data2
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: 0x000000C5 | line
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: 0x1C800031 | beacon time
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: 0xC8B3AFCF | tsf low
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: 0x00000000 | tsf hi
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: 0x00000000 | time gp1
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: 0xC8B52C71 | time gp2
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: 0x00000000 | time gp3
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: 0x0001291C | uCode version
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: 0x00000084 | hw version
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: 0x00488704 | board version
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: 0x09570048 | hcmd
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: 0x2FD63050 | isr0
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: 0x0103E000 | isr1
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: 0x00000002 | isr2
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: 0x0943FCC3 | isr3
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: 0x00000000 | isr4
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: 0x00800110 | isr_pref
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: 0x00007FFA | wait_event
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: 0x00000080 | l2p_control
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: 0x00000000 | l2p_duration
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: 0x0000003F | l2p_mhvalid
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: 0x00200200 | l2p_addr_match
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: 0x00000007 | lmpm_pmg_sel
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: 0x08121602 | timestamp
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: 0x0000F000 | flow_handler
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: Start IWL Event Log Dump: display last 20 entries
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: EVT_LOGT:3367316396:0x00000187:0736
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: EVT_LOGT:3367316414:0x00000000:0708
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: EVT_LOGT:3367316416:0x00000187:0736
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: EVT_LOGT:3367316434:0x00000000:0708
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: EVT_LOGT:3367316436:0x00000187:0736
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: EVT_LOGT:3367316454:0x00000000:0708
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: EVT_LOGT:3367316456:0x00000187:0736
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: EVT_LOGT:3367316474:0x00000000:0708
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: EVT_LOGT:3367316476:0x00000187:0736
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: EVT_LOGT:3367316494:0x00000000:0708
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: EVT_LOGT:3367316496:0x00000187:0736
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: EVT_LOGT:3367316514:0x00000000:0708
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: EVT_LOGT:3367316516:0x00000187:0736
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: EVT_LOGT:3367316534:0x00000000:0708
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: EVT_LOGT:3367316536:0x00000187:0736
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: EVT_LOGT:3367316554:0x00000000:0708
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: EVT_LOGT:3367316556:0x00000187:0736
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: EVT_LOGT:3367316574:0x00000000:0708
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: EVT_LOGT:3367316576:0x00000187:0736
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: EVT_LOGT:3367316616:0x00000000:0125
[Tue Oct  8 12:10:27 2019] ieee80211 phy0: Hardware restart was requested
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: Radio type=0x1-0x2-0x0
[Tue Oct  8 12:10:27 2019] iwlwifi 0000:01:00.0: Radio type=0x1-0x2-0x0

Similar investigation is in bug 203277 comment 2.

[1] https://wireless.wiki.kernel.org/en/users/drivers/iwlwifi#firmware
[2] https://wireless.wiki.kernel.org/en/users/drivers/iwlwifi/debugging#firmware_debugging
[3] https://forum.manjaro.org/t/sovled-iwlwifi-crashing-problem/82689/5
[4] https://ubuntuforums.org/showthread.php?t=2360828&p=13643217#post13643217
[5] https://askubuntu.com/a/355356/164142
[6] https://askubuntu.com/a/1177803/164142
Comment 1 Dmitry 2019-10-09 07:46:12 UTC 
Probably necessary to add that when hostapd is started, it brings wlan0 to promiscuous mode and adds it to br0:

dmesg:

[Tue Oct  8 11:14:19 2019] IPv6: ADDRCONF(NETDEV_UP): br0: link is not ready
[Tue Oct  8 11:14:19 2019] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[Tue Oct  8 11:14:19 2019] br0: port 3(wlan0) entered blocking state
[Tue Oct  8 11:14:19 2019] br0: port 3(wlan0) entered disabled state
[Tue Oct  8 11:14:19 2019] device wlan0 entered promiscuous mode
[Tue Oct  8 11:14:19 2019] br0: port 3(wlan0) entered blocking state
[Tue Oct  8 11:14:19 2019] br0: port 3(wlan0) entered forwarding state
[Tue Oct  8 11:14:19 2019] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[Tue Oct  8 11:14:19 2019] IPv6: ADDRCONF(NETDEV_CHANGE): br0: link becomes ready

# brctl show br0
bridge name     bridge id               STP enabled     interfaces
br0             8000.80ee73a68b94       no              eth0
                                                        eth1
                                                        wlan0