iprowifi3945 goes "no link" every 5 minutes

[ttcoder]

On my primary laptop (lenovo R61), wi-fi is less reliable in the newer hrevs: the connection is lost after a few minutes, then after about 15 seconds, the link comes back up and I can resume browsing the web. Rince and repeat every few minutes.

DHCP is not even renegotiated (does not get mentionned in the syslog at any rate), the link just comes back up. So this seems to be a driver issue.

Didn't try to go "static" (vs DHCP). But in previous hrevs (freebsd9 drivers?) the connection was solid. For instance in hrev50465

Let me know if you need any info, try builds ..etc to help with this, as we go into the beta1 dev cycle

[ttcoder]

~/Desktop> uname -a
Haiku shredder 1 hrev52079 Jul  7 2018 09:16:33 BePC x86 Haiku
~/Desktop> ifconfig /dev/net/iprowifi3945/0 -ht
~/Desktop> listdev
...
device Network controller [2|80|0]
  vendor 8086: Intel Corporation
  device 4227: PRO/Wireless 3945ABG [Golan] Network Connection

Edit: will also post a syslog, which includes a "firmware error" message:

KERN: [net/iprowifi3945/0] [d0:ae:ec:3e:a9:b0] sta power save mode on
KERN: [iprowifi3945] (wpi) fatal firmware error
KERN: wpi_fatal_intr: invalid count field (count = 0)
KERN: [net/iprowifi3945/0] stop running, 1 vaps running

[waddlesplash]

What hrev is this?

[ttcoder]

@waddlesplash - Running a USB thumbdrive with hrev52079 (so that my production environment remains pristine); but I can update it as needed

[ttcoder]

when wifi goes down and then back up : mentions "firmware error", "authentication expired" and other interesting things

[waddlesplash]

If you could try a FreeBSD 11.1 image and see if it behaves the same there, that would be helpful.

[waddlesplash]

Also, perhaps try using the older firmware -- i.e. blacklist the existing firmware, and drop ​https://git.kernel.org/pub/scm/linux/kernel/git/firmware/linux-firmware.git/plain/iwlwifi-3945-2.ucode into the appropriate non-packaged directory. It seems Linux still uses that firmware, anyway.

[waddlesplash]

Try re-testing after hrev52091; I've disabled hardware AES which the FreeBSD developers suggested.

[pulkomandy]

I'm getting linkdown/linkup notifications sometimes as well. It reconnects quite fast here but that may depend on the AP being used (unencrypted public wifi, so no WPA negociation needed).

[ttcoder]

@waddlesplash No change with the alternate firmware in place:

But I believe this is because the alternate and base one are the same by for byte:

/boot/system/non-packaged/data/firmware/iprowifi3945> cmp iwlwifi-3945-2.ucode /boot/system/data/firmware/iprowifi3945/iwlwifi-3945-2.ucode
/boot/system/non-packaged/data/firmware/iprowifi3945> 

(ran that before the blacklisting came into effect on reboot of course)

Can't find another file for 3945 in the directory listing over at ​https://git.kernel.org/pub/scm/linux/kernel/git/firmware/linux-firmware.git/plain/

Do you remember what prompted you to think of an alternate firmware file? Maybe you actually found one and just pasted the wrong link ? I'm all setup for trying another one if we find one :-)

This is with hrev52094 so includes the AES encryption change BTW

---

Misc details:

I see DHCP renewals in syslog, now. Maybe there were there before and eluded me.

---

Trying FreeBSD on this laptop is a bit of a long shot... Maybe if there exists a "FreeBSD on USB thumbdrive" thing like exists with Haiku..

--- EDIT: found some files, experimenting, will report back soon

[ttcoder]

@waddlesplash so I actually was able to test, with the files below (sound right? they look legit)

Found a half dozen firmwares via ​http://www.intellinuxwireless.org/ : ​https://wireless.wiki.kernel.org/en/users/drivers/iwlegacy Had to rename the older files as they are suffixed "-1" instead of "-2" and the driver was failing to find the firmware

Test results:

• iwlwifi-3945-ucode-15.28.1.6 : net disappears before login, exactly as in ticket #14266 (!)
• iwlwifi-3945-ucode-15.28.1.8 : intermittent "no link"
• iwlwifi-3945-ucode-15.28.2.8 : intermittent "no link"
• iwlwifi-3945-ucode-15.32.2.9 : intermittent "no link"

So going back to older firmwares, things are not better.

Worst case, when beta1 comes out I could create a "franken-rev" haiku, mix and match the beta1 image with the old driver; I guess the freebsd stuff is statically linked into each driver, so that idea could work ? I'm guessing if I drop the old driver binary in place, I'll get the old driver code with the old freebsd code

EDIT:

• latest findings in ticket:14266#comment:3 : in both tickets there is a "station de-auth" message in syslog
• also korli mentionned in another ticket that there exists FreeBSD11-like images over at ​https://download.trueos.org/master/amd64/

So my updated to-do list would be:

• frankenstein-rev
• TrueOS (BSD)
• static instead of DHCP
• some SotA wpa_supplicant debugging by mmlr in ticket:9646#comment:1

[waddlesplash]

Well, if this only affects one chipset, it's probably not a huge issue then. Removing from beta1.

[ttcoder]

No change in hrev52539

I'm not using this older laptop all that much any more, so no biggie if browsing gets interrupted AFAIC.

FWIW I looked at the syslog 'live' and saw this when the link went down..

KERN: [iprowifi3945] (wpi) fatal firmware error
KERN: wpi_fatal_intr: invalid count field (count = 0)
KERN: [net/iprowifi3945/0] stop running, 1 vaps running
KERN: [net/iprowifi3945/0] ieee80211_new_state_locked: RUN -> INIT (nrunning 0 nscanning 0)
KERN: [net/iprowifi3945/0] down parent 
KERN: ieee80211_notify_scan_done
KERN: [net/iprowifi3945/0] ieee80211_newstate_cb: RUN -> INIT arg -1
(2 screens' worth..)

And I think there was this when it came back up

KERN: ieee80211_notify_scan_done
KERN: wlan_control: 9235, 76
KERN: ifmedia_ioctl: switching wlan to   Type: IEEE 802.11 Wireless Ethernet
KERN:   Mode: autoselect
KERN:   SubType: autoselect
KERN: wlan_control: 9234, 18
KERN: wlan_control: 9234, 7
(2 screens worth of tracing deleted)

[waddlesplash]

Please retest after hrev52744 (but it's probably the same.)

[ttcoder]

Same symptoms cold booting into an hrev52801 USB stick. Syslog mentions "station deauth", plus a DHCP re-negociation (probably was there last time I posted too, just had missed it).

I'll have better news to report about an ipro4965 laptop soon though. But this one however is showing its age and relegated to secondary use, mainly running a pre-pm (!) hrev that runs networking flawlessly (go figure!)

[liss21]

Same thing on hrev53992. Installed on HDD. Every 5 minutes it renewal DHCP lease.

[davidrg]

I've installed beta2 on an HP nc6400 and aside from this issue and what I assume is a lack of a proper touchpad driver (no touchpad preferences anywhere to be seen) it runs perfectly.

In syslog whenever this happens I see:

KERN: [iprowifi3945] (wpi) fatal firmware error
KERN: firmware error log (count = 1):
KERN:   error type = "SYSASSERT" (0x00000005)
KERN:   error data      = 0x0000010B
KERN:   branch link     = 0x000008B60000035E
KERN:   interrupt link  = 0x0000032000000000
KERN:   time            = 4205944252
KERN: driver status:
KERN:   tx ring  0: qid=0  cur=5   queued=0  
KERN:   tx ring  1: qid=1  cur=0   queued=0  
KERN:   tx ring  2: qid=2  cur=0   queued=0  
KERN:   tx ring  3: qid=3  cur=4   queued=0  
KERN:   tx ring  4: qid=4  cur=43  queued=0  
KERN:   rx ring: cur=58
KERN: [net/iprowifi3945/0] stop running, 1 vaps running
KERN: [net/iprowifi3945/0] ieee80211_new_state_locked: RUN -> INIT (nrunning 0 nscanning 0)
KERN: [net/iprowifi3945/0] down parent 
KERN: ieee80211_notify_scan_done
KERN: [net/iprowifi3945/0] ieee80211_newstate_cb: RUN -> INIT arg -1
KERN: [net/iprowifi3945/0] sta_newstate: RUN -> INIT (-1)
KERN: [net/iprowifi3945/0] ieee80211_ref_node (ieee80211_send_mgmt:2463) 0x8c3ae000<fe:ec:da:f4:d3:60> refcnt 4
KERN: [net/iprowifi3945/0] [fe:ec:da:f4:d3:60] send station disassociate (reason: 8 (sending STA is leaving/has left BSS))
KERN: ieee80211_notify_node_leave
KERN: [net/iprowifi3945/0] node_reclaim: remove 0x8c3ae000<fe:ec:da:f4:d3:60> from station table, refcnt 3
KERN: [net/iprowifi3945/0] ieee80211_alloc_node 0x8c3aa000<00:1b:77:33:66:b6> in station table
KERN: [net/iprowifi3945/0] [00:1b:77:33:66:b6] ieee80211_alloc_node: inact_reload 2
KERN: ieee80211_notify_radio not implemented, yet.
KERN: [net/iprowifi3945/0] start running, 0 vaps running
KERN: [net/iprowifi3945/0] ieee80211_start_locked: up parent 
KERN: /dev/net/iprowifi3945/0: media change, media 0x300a0 quality 1000 speed 0
KERN: wlan_control: 9235, 76
KERN: wlan_control: 9234, 20
KERN: Last message repeated 2 times.
KERN: ieee80211_notify_radio not implemented, yet.
KERN: [net/iprowifi3945/0] start running, 1 vaps running
KERN: ifmedia_ioctl: switching wlan to   Type: IEEE 802.11 Wireless Ethernet
KERN:   Mode: autoselect
KERN:   SubType: autoselect
KERN: wlan_control: 9234, 16
KERN: wlan_control: 9234, 17
KERN: wlan_control: 9234, 26
KERN: wlan_open(0x82a02400)
KERN: [net/iprowifi3945/0] ieee80211_init
KERN: [net/iprowifi3945/0] start running, 1 vaps running
Last message repeated 1 time
KERN: wlan_control: 9234, 103
KERN: [net/iprowifi3945/0] ieee80211_new_state_locked: INIT -> SCAN (nrunning 0 nscanning 0)
KERN: [net/iprowifi3945/0] ieee80211_newstate_cb: INIT -> SCAN arg 0
KERN: [net/iprowifi3945/0] sta_newstate: INIT -> SCAN (0)
KERN: ieee80211_notify_scan_done
KERN: wlan_control: 9235, 76
KERN: ifmedia_ioctl: switching wlan to   Type: IEEE 802.11 Wireless Ethernet
KERN:   Mode: autoselect
KERN:   SubType: autoselect
KERN: wlan_control: 9234, 18
KERN: wlan_control: 9234, 7
KERN: wlan_control: 9234, 95
KERN: wlan_control: 9234, 17
KERN: wlan_control: 9234, 26
KERN: wlan_open(0x82a02400)
KERN: [net/iprowifi3945/0] ieee80211_init
KERN: [net/iprowifi3945/0] start running, 1 vaps running
KERN: wlan_control: 9234, 21
KERN: [net/iprowifi3945/0] [fe:ec:da:f4:d3:60] station assoc via MLME
KERN: [net/iprowifi3945/0] ieee80211_alloc_node 0x8c3ae000<fe:ec:da:f4:d3:60> in station table
KERN: [net/iprowifi3945/0] [fe:ec:da:f4:d3:60] ieee80211_alloc_node: inact_reload 2
KERN: [net/iprowifi3945/0] node_reclaim: remove 0x8c3aa000<00:1b:77:33:66:b6> from station table, refcnt 0
KERN: [net/iprowifi3945/0] set WME_AC_BE (chan) [acm 0 aifsn 3 logcwmin 4 logcwmax 10 txop 0]
KERN: [net/iprowifi3945/0] set WME_AC_BE (bss ) [acm 0 aifsn 3 logcwmin 4 logcwmax 10 txop 0]
KERN: [net/iprowifi3945/0] set WME_AC_BK (chan) [acm 0 aifsn 7 logcwmin 4 logcwmax 10 txop 0]
KERN: [net/iprowifi3945/0] set WME_AC_BK (bss ) [acm 0 aifsn 7 logcwmin 4 logcwmax 10 txop 0]
KERN: [net/iprowifi3945/0] set WME_AC_VI (chan) [acm 0 aifsn 2 logcwmin 3 logcwmax 4 txop 94]
KERN: [net/iprowifi3945/0] set WME_AC_VI (bss ) [acm 0 aifsn 2 logcwmin 3 logcwmax 4 txop 94]
KERN: [net/iprowifi3945/0] set WME_AC_VO (chan) [acm 0 aifsn 2 logcwmin 2 logcwmax 3 txop 47]
KERN: [net/iprowifi3945/0] set WME_AC_VO (bss ) [acm 0 aifsn 2 logcwmin 2 logcwmax 3 txop 47]
KERN: [net/iprowifi3945/0] update WME_AC_BE (chan+bss) [acm 0 aifsn 2 logcwmin 4 logcwmax 10 txop 0]
KERN: [net/iprowifi3945/0] ieee80211_wme_updateparams_locked: WME params updated, cap_info 0x0
KERN: [net/iprowifi3945/0] ieee80211_new_state_locked: SCAN -> AUTH (nrunning 0 nscanning 0)
KERN: [net/iprowifi3945/0] ieee80211_newstate_cb: SCAN -> AUTH arg 192
KERN: [net/iprowifi3945/0] sta_newstate: SCAN -> AUTH (192)
KERN: [net/iprowifi3945/0] ieee80211_ref_node (ieee80211_send_mgmt:2463) 0x8c3ae000<fe:ec:da:f4:d3:60> refcnt 3
KERN: [net/iprowifi3945/0] [fe:ec:da:f4:d3:60] recv auth frame with algorithm 0 seq 2
KERN: [net/iprowifi3945/0] ieee80211_new_state_locked: AUTH -> ASSOC (nrunning 0 nscanning 0)
KERN: [net/iprowifi3945/0] ieee80211_newstate_cb: AUTH -> ASSOC arg 0
KERN: [net/iprowifi3945/0] sta_newstate: AUTH -> ASSOC (0)
KERN: [net/iprowifi3945/0] ieee80211_ref_node (ieee80211_send_mgmt:2463) 0x8c3ae000<fe:ec:da:f4:d3:60> refcnt 3
KERN: [net/iprowifi3945/0] ieee80211_wme_updateparams_locked: WME params updated, cap_info 0x0
KERN: [net/iprowifi3945/0] [fe:ec:da:f4:d3:60] assoc success at aid 7: short preamble, short slot time, QoS
KERN: [net/iprowifi3945/0] ieee80211_new_state_locked: ASSOC -> RUN (nrunning 0 nscanning 0)
KERN: [net/iprowifi3945/0] ieee80211_newstate_cb: ASSOC -> RUN arg 16
KERN: [net/iprowifi3945/0] sta_newstate: ASSOC -> RUN (16)
KERN: ieee80211_notify_node_join
KERN: [net/iprowifi3945/0] [fe:ec:da:f4:d3:60] ieee80211_node_authorize: inact_reload 20
KERN: wlan_control: 9235, 15
KERN: /dev/net/iprowifi3945/0: media change, media 0x8300af quality 1000 speed 36000000
KERN: wlan_control: 9235, 1
DAEMON 'DHCP': /dev/net/iprowifi3945/0: Send DHCP_REQUEST for 10.1.1.154 to 255.255.255.255:67
DAEMON 'DHCP': /dev/net/iprowifi3945/0: Received DHCP_NACK from 10.0.1.29
DAEMON 'DHCP': /dev/net/iprowifi3945/0: Send DHCP_DISCOVER to 255.255.255.255:67
DAEMON 'DHCP': /dev/net/iprowifi3945/0: Timeout shift: 500 msecs (try 1)
DAEMON 'DHCP': /dev/net/iprowifi3945/0: Send DHCP_DISCOVER to 255.255.255.255:67
DAEMON 'DHCP': /dev/net/iprowifi3945/0: Timeout shift: 1000 msecs (try 2)
DAEMON 'DHCP': /dev/net/iprowifi3945/0: Send DHCP_DISCOVER to 255.255.255.255:67
KERN: wlan_control: 9235, 1
KERN: wlan_control: 9235, 15
KERN: wlan_control: 9234, 19
DAEMON 'DHCP': /dev/net/iprowifi3945/0: Timeout shift: 2000 msecs (try 3)
DAEMON 'DHCP': /dev/net/iprowifi3945/0: Send DHCP_DISCOVER to 255.255.255.255:67
DAEMON 'DHCP': /dev/net/iprowifi3945/0: Received DHCP_OFFER from 10.1.1.1
DAEMON 'DHCP':   your_address: 10.1.1.154
DAEMON 'DHCP':   server: 10.1.1.1
DAEMON 'DHCP':   lease time: 86400 seconds
DAEMON 'DHCP':   subnet: 255.255.255.0
DAEMON 'DHCP':   gateway: 10.1.1.1
DAEMON 'DHCP':   nameserver[0]: 10.1.1.1
DAEMON 'DHCP': /dev/net/iprowifi3945/0: Send DHCP_REQUEST for 10.1.1.154 to 255.255.255.255:67
DAEMON 'DHCP': /dev/net/iprowifi3945/0: Received DHCP_ACK from 10.1.1.1
DAEMON 'DHCP':   server: 10.1.1.1
DAEMON 'DHCP':   lease time: 86400 seconds
DAEMON 'DHCP':   subnet: 255.255.255.0
DAEMON 'DHCP':   gateway: 10.1.1.1
DAEMON 'DHCP':   nameserver[0]: 10.1.1.1
DAEMON 'DHCP': /dev/net/iprowifi3945/0: DHCP status = No error
KERN: wlan_control: 9234, 19

[waddlesplash]

I did not find anything here that would be a significant difference vs. FreeBSD, so, it seems likely this is actually a FreeBSD driver bug. I did not look upstream for issues however.

[waddlesplash]

Please retest with a recent (hrev56182+) nightly, if you can.

[davidrg]

I upgraded to the latest nightly (hrev56182)but now I just end up in KDL on boot (screenshot: ​https://www.zx.net.nz/~david/images/haiku_56182_iprowifi3945_kdl.png)

I can type continue and it does make it to the desktop OK, just with no WiFi adapter.

[waddlesplash]

Please attach KDL photos here, as a general rule.

This is useful, thanks. I'll investigate a bit.

[waddlesplash]

Please test after hrev56185, it should resolve this problem.

[davidrg]

Now on hrev56191 - no more KDL on startup. Wifi seems more stable than before - its no longer failing every 5 minutes. It did reconnect very quickly in the space of 30 minutes or so for no obvious reason but this didn't interrupt an ongoing FTP transfer and there was nothing interesting in syslog.

It did eventually fail in the same way as before though with it fully disconnecting for a few seconds with a bunch of stuff written to syslog - see the end of syslog_hrev56191. There also seems to be a large number of "wlan_control" messages being logged - not sure if this is normal.

[waddlesplash]

Out of curiosity, does this machine have more than 4GB of RAM?

[waddlesplash]

Please retest again after hrev56205.

[davidrg]

This machine has 3GB installed (1GB onboard plus a 2GB SODIMM).

Now on hrev56213 and had a go downloading a 3GB file using FtpPositive. Towards the end of the transfer I ran into the same error as before which you can see in syslog_hrev56213

[davidrg]

syslog for hrev56213