Bug 280430

Summary:

iwlwifi: linuxkpi_ieee80211_connection_loss

Product:

Base System

Reporter:

Peter Much <pmc>

Component:

wireless

Assignee:

freebsd-wireless (Nobody) <wireless>

Status:

Open ---

Severity:

Affects Only Me

CC:

arrowd, bz, mmatalka

Priority:

---

Version:

13.3-RELEASE

Hardware:

amd64

OS:

Any

See Also:

https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=280546

Bug Depends on:

Bug Blocks:

273620

Attachments:

Description	Flags
Crash in wifi driver	none

Description Peter Much 2024-07-24 10:34:02 UTC

This is a minor iwlwifi issue, and, as I don't see that error msg reported anywhere here, I report it for completeness.

The error happens AFAIK only after boot, and only sometimes, so it can be workarounded simply by rebooting. It appeared first in 13.2 (after the main functionality had started to work well).

Utilizing dhclient, it will just beat the thing as long as it takes to make it behave - so now it fixes itself:

Jul 24 12:03:40 <console.info> cora kernel: [17] Starting dhclient.
Jul 24 12:03:40 <console.info> cora kernel: [17] wlan0: no link .....
Jul 24 12:03:40 <console.info> cora kernel: [20]  got link
Jul 24 12:03:40 <console.info> cora kernel: [20] DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Jul 24 12:03:40 <console.info> cora kernel: [20] wlan0 link state up -> down
Jul 24 12:03:40 <console.info> cora kernel: [22] DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Jul 24 12:03:40 <console.info> cora kernel: [22] wlan0 link state down -> up
Jul 24 12:03:40 <console.info> cora kernel: [22] DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Jul 24 12:03:40 <console.info> cora kernel: [23] wlan0 link state up -> down
Jul 24 12:03:40 <console.info> cora kernel: [24] wlan0 link state down -> up
Jul 24 12:03:40 <console.info> cora kernel: [24] DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Jul 24 12:03:40 <console.info> cora kernel: [25] wlan0 link state up -> down
Jul 24 12:03:40 <console.info> cora kernel: [25] wlan0 link state down -> up
Jul 24 12:03:40 <console.info> cora kernel: [25] DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Jul 24 12:03:40 <console.info> cora kernel: [26] wlan0 link state up -> down
Jul 24 12:03:40 <console.info> cora kernel: [28] DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Jul 24 12:03:40 <console.info> cora kernel: [34] DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Jul 24 12:03:40 <console.info> cora kernel: [37] wlan0 link state down -> up
Jul 24 12:03:40 <console.info> cora kernel: [37] DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Jul 24 12:03:40 <console.info> cora kernel: [38] wlan0 link state up -> down
Jul 24 12:03:40 <console.info> cora kernel: [44] DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Jul 24 12:03:40 <console.info> cora kernel: [53] DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 5
Jul 24 12:03:40 <console.info> cora kernel: [59] DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 14
Jul 24 12:03:40 <console.info> cora kernel: [61] wlan0 link state down -> up
Jul 24 12:03:40 <console.info> cora kernel: [61] DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Jul 24 12:03:40 <console.info> cora kernel: [61] wlan0 link state up -> down
Jul 24 12:03:40 <console.info> cora kernel: [63] DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Jul 24 12:03:40 <console.info> cora kernel: [70] DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Jul 24 12:03:40 <console.info> cora kernel: [72] DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 10
Jul 24 12:03:40 <console.info> cora kernel: [80] DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 6
Jul 24 12:03:40 <console.info> cora kernel: [86] DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 8
Jul 24 12:03:40 <console.info> cora kernel: [92] wlan0 link state down -> up
Jul 24 12:03:40 <console.info> cora kernel: [92] DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Jul 24 12:03:40 <console.info> cora kernel: [93] wlan0 link state up -> down
Jul 24 12:03:40 <console.info> cora kernel: [94] DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 6
Jul 24 12:03:40 <console.info> cora kernel: [95] DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Jul 24 12:03:40 <console.info> cora kernel: [100] DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 15
Jul 24 12:03:40 <console.info> cora kernel: [106] DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 4
Jul 24 12:03:40 <console.info> cora kernel: [110] DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 9
Jul 24 12:03:40 <console.info> cora kernel: [119] DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 21
Jul 24 12:03:40 <console.info> cora kernel: [141] DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 7
Jul 24 12:03:40 <console.info> cora kernel: [148] DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 8
Jul 24 12:03:40 <console.info> cora kernel: [155] DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 12
Jul 24 12:03:40 <console.info> cora kernel: [155] wlan0 link state down -> up
Jul 24 12:03:40 <console.info> cora kernel: [155] DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Jul 24 12:03:40 <console.info> cora kernel: [163] DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Jul 24 12:03:40 <console.info> cora kernel: [163] DHCPACK from 192.168.96.1
Jul 24 12:03:40 <console.info> cora kernel: [163] bound to 192.168.96.100 -- renewal in 21600 seconds.
------------------------------------------------

Jul 24 12:03:40 <kern.info> cora kernel: [16] Intel(R) Wireless WiFi based driver for FreeBSD
Jul 24 12:03:40 <kern.crit> cora kernel: [16] iwlwifi0: <iwlwifi> mem 0x6002138000-0x600213bfff at device 20.3 on pci0
Jul 24 12:03:40 <kern.crit> cora kernel: [16] iwlwifi0: Detected crf-id 0x3617, cnv-id 0x20000302 wfpm id 0x80000000
Jul 24 12:03:40 <kern.crit> cora kernel: [16] iwlwifi0: PCI dev a0f0/0074, rev=0x351, rfid=0x10a100
Jul 24 12:03:40 <kern.crit> cora kernel: [16] iwlwifi0: successfully loaded firmware image 'iwlwifi-QuZ-a0-hr-b0-77.ucode'
Jul 24 12:03:40 <kern.crit> cora kernel: [16] iwlwifi0: api flags index 2 larger than supported by driver
Jul 24 12:03:40 <kern.crit> cora kernel: [16] iwlwifi0: TLV_FW_FSEQ_VERSION: FSEQ Version: 89.3.35.37
Jul 24 12:03:40 <kern.crit> cora kernel: [16] iwlwifi0: loaded firmware version 77.2df8986f.0 QuZ-a0-hr-b0-77.ucode op_mode iwlmvm
Jul 24 12:03:40 <kern.crit> cora kernel: [16] iwlwifi0: Detected Intel(R) Wi-Fi 6 AX201 160MHz, REV=0x351
Jul 24 12:03:40 <kern.crit> cora kernel: [16] iwlwifi0: Detected RF HR B3, rfid=0x10a100
Jul 24 12:03:40 <kern.crit> cora kernel: [16] iwlwifi0: base HW address: 2c:6d:c1:5f:f3:7a
Jul 24 12:03:40 <kern.info> cora kernel: [16] wlan0: Ethernet address: 2c:6d:c1:5f:f3:7a
Jul 24 12:03:40 <kern.info> cora kernel: [19] wlan0: link state changed to UP
Jul 24 12:03:40 <kern.crit> cora kernel: [20] iwlwifi0: No beacon heard and the session protection is over already...
Jul 24 12:03:40 <kern.crit> cora kernel: [20] iwlwifi0: linuxkpi_ieee80211_connection_loss: vif 0xfffffe00baef4e80 vap 0xfffffe00baef4010 state RUN
Jul 24 12:03:40 <kern.info> cora kernel: [20] wlan0: link state changed to DOWN
Jul 24 12:03:40 <kern.info> cora kernel: [22] wlan0: link state changed to UP
Jul 24 12:03:40 <kern.crit> cora kernel: [23] iwlwifi0: No beacon heard and the session protection is over already...
Jul 24 12:03:40 <kern.crit> cora kernel: [23] iwlwifi0: linuxkpi_ieee80211_connection_loss: vif 0xfffffe00baef4e80 vap 0xfffffe00baef4010 state RUN
Jul 24 12:03:40 <kern.info> cora kernel: [23] wlan0: link state changed to DOWN
Jul 24 12:03:40 <kern.info> cora kernel: [24] wlan0: link state changed to UP
Jul 24 12:03:40 <kern.crit> cora kernel: [25] iwlwifi0: No beacon heard and the session protection is over already...
Jul 24 12:03:40 <kern.crit> cora kernel: [25] iwlwifi0: linuxkpi_ieee80211_connection_loss: vif 0xfffffe00baef4e80 vap 0xfffffe00baef4010 state RUN
Jul 24 12:03:40 <kern.info> cora kernel: [25] wlan0: link state changed to DOWN
Jul 24 12:03:40 <kern.info> cora kernel: [25] wlan0: link state changed to UP
Jul 24 12:03:40 <kern.crit> cora kernel: [26] iwlwifi0: No beacon heard and the session protection is over already...
Jul 24 12:03:40 <kern.crit> cora kernel: [26] iwlwifi0: linuxkpi_ieee80211_connection_loss: vif 0xfffffe00baef4e80 vap 0xfffffe00baef4010 state RUN
Jul 24 12:03:40 <kern.info> cora kernel: [26] wlan0: link state changed to DOWN
Jul 24 12:03:40 <kern.info> cora kernel: [37] wlan0: link state changed to UP
Jul 24 12:03:40 <kern.crit> cora kernel: [38] iwlwifi0: No beacon heard and the session protection is over already...
Jul 24 12:03:40 <kern.crit> cora kernel: [38] iwlwifi0: linuxkpi_ieee80211_connection_loss: vif 0xfffffe00baef4e80 vap 0xfffffe00baef4010 state RUN
Jul 24 12:03:40 <kern.info> cora kernel: [38] wlan0: link state changed to DOWN
Jul 24 12:03:40 <kern.info> cora kernel: [61] wlan0: link state changed to UP
Jul 24 12:03:40 <kern.crit> cora kernel: [61] iwlwifi0: No beacon heard and the session protection is over already...
Jul 24 12:03:40 <kern.crit> cora kernel: [61] iwlwifi0: linuxkpi_ieee80211_connection_loss: vif 0xfffffe00baef4e80 vap 0xfffffe00baef4010 state RUN
Jul 24 12:03:40 <kern.info> cora kernel: [61] wlan0: link state changed to DOWN
Jul 24 12:03:40 <kern.info> cora kernel: [92] wlan0: link state changed to UP
Jul 24 12:03:40 <kern.crit> cora kernel: [93] iwlwifi0: No beacon heard and the session protection is over already...
Jul 24 12:03:40 <kern.crit> cora kernel: [93] iwlwifi0: linuxkpi_ieee80211_connection_loss: vif 0xfffffe00baef4e80 vap 0xfffffe00baef4010 state RUN
Jul 24 12:03:40 <kern.info> cora kernel: [93] wlan0: link state changed to DOWN
Jul 24 12:03:40 <kern.info> cora kernel: [155] wlan0: link state changed to UP
Jul 24 12:03:40 <kern.info> cora kernel: [169] tun0: link state changed to UP

Comment 1 Bjoern A. Zeeb freebsd_committer

2024-07-25 16:15:18 UTC

If it is still reproducible how are scan results (before the reboot)?

Is your environment/channel/neighbourhood noisy?

What if you move closer/further away from the AP?

Comment 2 Peter Much 2024-07-27 09:31:05 UTC

Hi Bjoern, pleased to read You!

No, this is residential houses with few parties each; I usually see 4-6 stations and max one on neighour channel. Unless there is some crazy radio amateur around, I think radio noise is unlikely.

But You drive my thinking to something else: if it's signal quality related, could it also be a bug in the AP (old consumer device, and I know it has bugs)?

As far as I can still gather my travel logs and system logs, it seems this specific behaviour did not appear at my other location (that one has different patterns, connection loss during the night, but apparently not this one after boot).

Comment 3 Bjoern A. Zeeb freebsd_committer

2024-07-28 11:49:38 UTC

(In reply to Peter Much from comment #2)

Given it says "no beacon heard";
you may have a chance to change the Beacon Interval on your AP.

But this could also be a filtering problem.

I think the question remaining is:
is this reproducible at that location even across boots or days?

Comment 4 Gleb Popov freebsd_committer

2024-09-03 13:54:48 UTC

Not sure if this is the same problem or a different bug, but this is what I got on a July CURRENT:

iwlwifi0: linuxkpi_ieee80211_beacon_loss: vif 0xfffffe0119e90e80 vap 0xfffffe0119e90010 state RUN
iwlwifi0: linuxkpi_ieee80211_beacon_loss: vif 0xfffffe0119e90e80 vap 0xfffffe0119e90010 state RUN
wlan0: link state changed to DOWN
iwlwifi0: Microcode SW error detected.  Restarting 0x2000000.
iwlwifi0: Start IWL Error Log Dump:
iwlwifi0: Transport status: 0x0000004B, valid: 6
iwlwifi0: Loaded firmware version: 29.4063824552.0 7265D-29.ucode
iwlwifi0: 0x000021A0 | ADVANCED_SYSASSERT          
iwlwifi0: 0x00000220 | trm_hw_status0
iwlwifi0: 0x00000000 | trm_hw_status1
iwlwifi0: 0x00043D6C | branchlink2
iwlwifi0: 0x0004B002 | interruptlink1
iwlwifi0: 0x00000000 | interruptlink2
iwlwifi0: 0x00000020 | data1
iwlwifi0: 0x00000000 | data2
iwlwifi0: 0x00000000 | data3
iwlwifi0: 0xDDC11B99 | beacon time
iwlwifi0: 0xEC7D5468 | tsf low
iwlwifi0: 0x0000002E | tsf hi
iwlwifi0: 0x00000000 | time gp1
iwlwifi0: 0x6BA6E606 | time gp2
iwlwifi0: 0x00000001 | uCode revision type
iwlwifi0: 0x0000001D | uCode version major
iwlwifi0: 0xF2390AA8 | uCode version minor
iwlwifi0: 0x00000210 | hw version
iwlwifi0: 0x00489200 | board version
iwlwifi0: 0x007D0118 | hcmd
iwlwifi0: 0x24022080 | isr0
iwlwifi0: 0x00000000 | isr1
iwlwifi0: 0x00000002 | isr2
iwlwifi0: 0x404150C0 | isr3
iwlwifi0: 0x00000000 | isr4
iwlwifi0: 0x007C019F | last cmd Id
iwlwifi0: 0x00000000 | wait_event
iwlwifi0: 0x000000D4 | l2p_control
iwlwifi0: 0x00018010 | l2p_duration
iwlwifi0: 0x00000007 | l2p_mhvalid
iwlwifi0: 0x00000000 | l2p_addr_match
iwlwifi0: 0x00000005 | lmpm_pmg_sel
iwlwifi0: 0x03031934 | timestamp
iwlwifi0: 0x00008898 | flow_handler
iwlwifi0: Fseq Registers:
iwlwifi0: 0x00000000 | FSEQ_ERROR_CODE
iwlwifi0: 0x00000000 | FSEQ_TOP_INIT_VERSION
iwlwifi0: 0x00000000 | FSEQ_CNVIO_INIT_VERSION
iwlwifi0: 0x00000000 | FSEQ_OTP_VERSION
iwlwifi0: 0x00000000 | FSEQ_TOP_CONTENT_VERSION
iwlwifi0: 0x00000000 | FSEQ_ALIVE_TOKEN
iwlwifi0: 0x00000000 | FSEQ_CNVI_ID
iwlwifi0: 0x00000000 | FSEQ_CNVR_ID
iwlwifi0: 0x00000000 | CNVI_AUX_MISC_CHIP
iwlwifi0: 0x00000000 | CNVR_AUX_MISC_CHIP
iwlwifi0: 0x00000000 | CNVR_SCU_SD_REGS_SD_REG_DIG_DCDC_VTRIM
iwlwifi0: 0x00000000 | CNVR_SCU_SD_REGS_SD_REG_ACTIVE_VDIG_MIRROR
iwlwifi0: 0x00000000 | FSEQ_PREV_CNVIO_INIT_VERSION
iwlwifi0: 0x00000000 | FSEQ_WIFI_FSEQ_VERSION
iwlwifi0: 0x00000000 | FSEQ_BT_FSEQ_VERSION
iwlwifi0: 0x00000000 | FSEQ_CLASS_TP_VERSION
iwlwifi0: Collecting data: trigger 2 fired.
iwlwifi0: FW error in SYNC CMD ADD_STA
#0 0xffffffff80a6287b at linux_dump_stack+0x1b
#1 0xffffffff82fcebb6 at iwl_trans_txq_send_hcmd+0x3e6
#2 0xffffffff82f6b2ad at iwl_trans_send_cmd+0xcd
#3 0xffffffff82fae198 at iwl_mvm_send_cmd_status+0x28
#4 0xffffffff82fae29f at iwl_mvm_send_cmd_pdu_status+0x4f
#5 0xffffffff82f9bf2c at iwl_mvm_sta_send_to_fw+0x35c
#6 0xffffffff82f9e8ec at iwl_mvm_add_sta+0x14c
#7 0xffffffff82f822a6 at iwl_mvm_mac_sta_state_common+0x626
#8 0xffffffff80a5d1b3 at lkpi_80211_mo_sta_state+0x33
#9 0xffffffff80a53c79 at lkpi_sta_scan_to_auth+0x599
#10 0xffffffff80a5446b at lkpi_sta_assoc_to_auth+0x1b
#11 0xffffffff80a5c973 at lkpi_iv_newstate+0x3b3
#12 0xffffffff8098563c at ieee80211_newstate_cb+0x1fc
#13 0xffffffff8084a7a2 at taskqueue_run_locked+0x182
#14 0xffffffff8084b992 at taskqueue_thread_loop+0xc2
#15 0xffffffff8079e0fb at fork_exit+0x7b
#16 0xffffffff80c0962e at fork_trampoline+0xe
iwlwifi0: Couldn't send TIME_EVENT_CMD: -5
iwlwifi0: iwl_trans_wait_tx_queues_empty bad state = 0
iwlwifi0: Failed to send binding (action:3): -5
iwlwifi0: PHY ctxt cmd error. ret=-5
iwlwifi0: Scan failed! ret -5
iwlwifi0: ERROR: lkpi_ic_scan_start: hw_scan returned -5
iwlwifi0: Scan failed! ret -5
iwlwifi0: ERROR: lkpi_ic_scan_start: hw_scan returned -5
iwlwifi0: Scan failed! ret -5

Comment 5 Peter Much 2024-09-16 19:15:25 UTC

I happened to find another AP hidden in my DSL modem ;), and after switching to that one, the issue did never happen again.

So this is most likely a bug on the other side, i.e. within the former AP - and that is not at all unlikely, because I already found more bugs in that device, and it is very old and not worth considering any workaround.

So this one can be closed as far as I am concerned.

Comment 6 Bjoern A. Zeeb freebsd_committer

2024-09-16 20:43:21 UTC

(In reply to Peter Much from comment #5)

Thanks a lot for the feedback.  Can you for the records share what kind of AP the "old" one was?   May help others at some point.

Also should we close it then for now?

Comment 7 Peter Much 2024-09-16 22:16:52 UTC

(In reply to Bjoern A. Zeeb from comment #6)

Yes, sure.
That would be an SMC Barricade 54Mbps g Wireless Broadband Router SMCWBR14-G2 EU.

Comment 8 mmatalka 2024-12-13 21:37:06 UTC

(In reply to Gleb Popov from comment #4)
I am experience the same issue.  For me, it occurs when I am uploading.  The latency gets from high (as high as 6 seconds) and then this error shows up.  I have to restart the interface to get it to reconnect.  Uploads are also quite slow.

Comment 9 mmatalka 2024-12-18 16:36:15 UTC

Created attachment 255934 [details]
Crash in wifi driver

Comment 10 Bjoern A. Zeeb freebsd_committer

2024-12-18 17:52:40 UTC

(In reply to mmatalka from comment #9)

The crash in comment #9 (attachment) is a duplicate of bug 280546 it seems but not this one.