Context Navigation

#14260 new bug

iprowifi3945 goes "no link" every 5 minutes

Reported by:	ttcoder	Owned by:	waddlesplash
Priority:	normal	Milestone:	Unscheduled
Component:	Drivers/Network/iprowifi3945	Version:	R1/Development
Keywords:		Cc:
Blocked By:		Blocking:
Platform:	All

Description

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

Attachments (5)

syslog_sample (15.8 KB ) - added by ttcoder 6 years ago.: when wifi goes down and then back up : mentions "firmware error", "authentication expired" and other interesting things
haiku_56182_iprowifi3945_kdl.png (2.2 MB ) - added by waddlesplash 2 years ago.
Bruno iprowifi 3945.jpg (4.5 MB ) - added by bruno 2 years ago.
syslog_hrev56191 (62.2 KB ) - added by davidrg 2 years ago.
syslog_hrev56213 (383.8 KB ) - added by davidrg 2 years ago.: syslog for hrev56213

Change History (29)

comment:1 by ttcoder, 6 years ago

~/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

Edit2: not sure if it's significant at all, but there are "Tx errors", 39 after an hour or so of light browsing haiku tickets:

/dev/net/iprowifi3945/0
        Hardware type: Ethernet, Address: (my mac addy here)
        Network: (my net here), Address: (...), WPA2, PSK/CCMP
        inet addr: 192.168.1.10, Bcast: 192.168.1.255, Mask: 255.255.255.0
        MTU: 1500, Metric: 0, up broadcast link auto-configured
        Receive: 13725 packets, 0 errors, 11587106 bytes, 0 mcasts, 0 dropped
        Transmit: 13969 packets, 39 errors, 1639818 bytes, 0 mcasts, 0 dropped
        Collisions: 0

Last edited 6 years ago by ttcoder (previous) (diff)

comment:2 by waddlesplash, 6 years ago

What hrev is this?

comment:3 by ttcoder, 6 years ago

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

by ttcoder, 6 years ago

Attachment:	syslog_sample added

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

comment:4 by waddlesplash, 6 years ago

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

comment:5 by waddlesplash, 6 years ago

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.

comment:6 by waddlesplash, 6 years ago

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

comment:7 by pulkomandy, 6 years ago

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).

comment:8 by ttcoder, 6 years ago

@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

Last edited 6 years ago by ttcoder (previous) (diff)

comment:9 by ttcoder, 6 years ago

@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

Last edited 6 years ago by ttcoder (previous) (diff)

comment:10 by waddlesplash, 6 years ago

Milestone:	R1/beta1 → Unscheduled

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

comment:11 by ttcoder, 6 years ago

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)

comment:12 by waddlesplash, 6 years ago

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

comment:13 by ttcoder, 6 years ago

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!)

comment:14 by liss21, 5 years ago

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

comment:15 by davidrg, 4 years ago

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

comment:16 by waddlesplash, 4 years ago

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.

comment:17 by waddlesplash, 2 years ago

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

comment:18 by davidrg, 2 years ago

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.

by waddlesplash, 2 years ago

Attachment:	haiku_56182_iprowifi3945_kdl.png added

comment:19 by waddlesplash, 2 years ago

Please attach KDL photos here, as a general rule.

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

by bruno, 2 years ago

Attachment:	Bruno iprowifi 3945.jpg added

comment:20 by waddlesplash, 2 years ago

Please test after hrev56185, it should resolve this problem.

comment:21 by davidrg, 2 years ago

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.

by davidrg, 2 years ago

Attachment:	syslog_hrev56191 added

comment:22 by waddlesplash, 2 years ago

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

comment:23 by waddlesplash, 2 years ago

Please retest again after hrev56205.

comment:24 by davidrg, 2 years ago

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

by davidrg, 2 years ago

Attachment:	syslog_hrev56213 added

syslog for hrev56213

Note: See TracTickets for help on using tickets.

Download in other formats: