Bug 233226 - run(4) WiFi card fails periodically: run0: device timeout
Summary: run(4) WiFi card fails periodically: run0: device timeout
Status: New
Alias: None
Product: Base System
Classification: Unclassified
Component: wireless (show other bugs)
Version: CURRENT
Hardware: Any Any
: --- Affects Some People
Assignee: freebsd-wireless (Nobody)
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2018-11-14 17:16 UTC by Yuri Victorovich
Modified: 2019-12-03 16:42 UTC (History)
3 users (show)

See Also:

Attachments
Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.
Description Yuri Victorovich freebsd_committer freebsd_triage 2018-11-14 17:16:48 UTC 
I don't think this is a regression, this has been happening for a long time.

> $ grep timeout /var/log/messages
> Nov 11 19:52:57 xx kernel: run0: device timeout
> Nov 13 14:10:37 xx kernel: run0: device timeout
> Nov 13 15:05:14 xx kernel: run0: device timeout
> Nov 14 09:08:59 xx kernel: run0: device timeout

FreeBSD xx 12.0-ALPHA7 FreeBSD 12.0-ALPHA7 #2 r338897M: Sun Sep 23 23:36:22 PDT 2018     sw@sw:/usr/obj/usr/src/amd64.amd64/sys/GENERIC  amd64
Comment 1 Yuri Victorovich freebsd_committer freebsd_triage 2018-11-14 17:17:47 UTC 
Internet connection freezes for a while when this happens, and it comes back in a few minutes.
Comment 2 Jim Pirzyk freebsd_committer freebsd_triage 2019-09-12 12:36:23 UTC 
I have been seeing this issue in the last day as I just started using the interface as an AP.

158>uname -a
FreeBSD zephyr 12.0-RELEASE-p10 FreeBSD 12.0-RELEASE-p10 GENERIC  amd64

159>ifconfig wlan0
wlan0: flags=8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu 1500
	ether Y:Y:Y:Y:Y:Y
	inet X.X.X.X netmask 0xffffff00 broadcast X.X.X.255 
	groups: wlan 
	ssid HOSTID channel 1 (2412 MHz 11g) bssid Y:Y:Y:Y:Y:Y
	regdomain FCC country US authmode WPA2/802.11i privacy MIXED
	deftxkey 2 TKIP 2:128-bit TKIP 3:128-bit txpower 30 scanvalid 60
	protmode CTS wme hidessid dtimperiod 1 -dfs
	media: IEEE 802.11 Wireless Ethernet autoselect mode 11g <hostap>
	status: running
	nd6 options=29<PERFORMNUD,IFDISABLED,AUTO_LINKLOCAL>

and it lasts for a bit:

Sep 11 18:08:11 <kern.crit> zephyr kernel: run0: device timeout
Sep 11 18:08:46 <kern.crit> zephyr syslogd: last message repeated 7 times
Sep 11 18:10:50 <kern.crit> zephyr syslogd: last message repeated 25 times
Sep 11 18:11:59 <kern.crit> zephyr syslogd: last message repeated 14 times
...
Sep 11 18:14:35 <kern.crit> zephyr kernel: run0: firmware RT2870 ver. 0.33 loaded

Sep 11 22:57:22 <kern.crit> zephyr kernel: run0: device timeout
Sep 11 22:57:57 <kern.crit> zephyr syslogd: last message repeated 10 times
Sep 11 22:58:30 <kern.crit> zephyr syslogd: last message repeated 13 times

At the 18:11:59 time, I forced the interface down and back up to get it to reload.  I am not sure when the issue cleared after 22:57.
Comment 3 Jim Pirzyk freebsd_committer freebsd_triage 2019-09-12 13:36:33 UTC 
Forgot to add the hardware info:

run0: MAC/BBP RT3070 (rev 0x0201), RF RT3020 (MIMO 1T1R), address Y:Y:Y:Y:Y:Y
Comment 4 Ashish Gupta 2019-09-30 19:51:30 UTC 
(In reply to Jim Pirzyk from comment #2)

Hi!

I'd like to reproduce this issue on my setup. I have an AP which forwards my traffic to/from another wireless interface on the same machine. Do you see these device timeouts when doing something specific (like watching an HD video / downloading large files, etc)?
Comment 5 Jim Pirzyk freebsd_committer freebsd_triage 2019-10-03 18:00:33 UTC 
No I have yet to discover a specific cause.  Most of the time I see the device timeouts are in the middle of the night.  But sometimes (like just within the hour) it will happen while I am using wireless, browsing web, slack, etc.

I turned on the hw.usb.run.debug=0x40 (USB_ERR_TIMEOUT) and this is what I see:

Oct  3 12:34:30 <kern.crit> zephyr kernel: transfer complete: 488 bytes @ index 1
Oct  3 12:34:30 <kern.crit> zephyr kernel: run0: sending frame len=132/160 @ index 1
Oct  3 12:34:35 <kern.crit> zephyr kernel: run0: USB transfer error, USB_ERR_TIMEOUT
Oct  3 12:34:35 <kern.crit> zephyr kernel: run0: device timeout
Oct  3 12:34:35 <kern.crit> zephyr kernel: run0: cmdq_store=5
Oct  3 12:34:35 <kern.crit> zephyr kernel: run0: sending frame len=389/420 @ index 1
Oct  3 12:34:35 <kern.crit> zephyr kernel: run0: transfer complete: 420 bytes @ index 1
Oct  3 12:34:35 <kern.crit> zephyr kernel: run0: sending frame len=1536/1564 @ index 1
Oct  3 12:34:37 <kern.crit> zephyr kernel: run0: sending frame len=126/156 @ index 0
Oct  3 12:34:37 <kern.crit> zephyr kernel: run0: transfer complete: 156 bytes @ index 0
Oct  3 12:34:37 <kern.crit> zephyr kernel: run0: sending frame len=126/156 @ index 0
Oct  3 12:34:37 <kern.crit> zephyr kernel: run0: transfer complete: 156 bytes @ index 0
Oct  3 12:34:40 <kern.crit> zephyr kernel: run0: USB transfer error, USB_ERR_TIMEOUT
Oct  3 12:34:40 <kern.crit> zephyr kernel: run0: device timeout
Oct  3 12:34:40 <kern.crit> zephyr kernel: run0: cmdq_store=2
Oct  3 12:34:40 <kern.crit> zephyr kernel: run0: sending frame len=1536/1564 @ index 1
Oct  3 12:34:45 <kern.crit> zephyr kernel: run0: USB transfer error, USB_ERR_TIMEOUT
Oct  3 12:34:45 <kern.crit> zephyr kernel: run0: device timeout
Oct  3 12:34:45 <kern.crit> zephyr kernel: run0: 
Oct  3 12:34:45 <kern.crit> zephyr kernel: cmdq_store=11
Oct  3 12:34:45 <kern.crit> zephyr kernel: run0: sending frame len=1536/1564 @ index 1
Oct  3 12:34:47 <kern.crit> zephyr kernel: run0: sending frame len=126/156 @ index 0
Oct  3 12:34:50 <kern.crit> zephyr kernel: run0: USB transfer error, USB_ERR_TIMEOUT
Oct  3 12:34:50 <kern.crit> zephyr kernel: run0: device timeout
Oct  3 12:34:50 <kern.crit> zephyr kernel: run0: cmdq_store=12
...
Oct  3 12:54:41 <kern.crit> zephyr kernel: run0: sending frame len=26/56 @ index 0
Oct  3 12:54:41 <kern.crit> zephyr kernel: run0: transfer complete: 56 bytes @ index 0
Oct  3 12:54:41 <kern.crit> zephyr kernel: run0: sending frame len=26/56 @ index 0
Oct  3 12:54:41 <kern.crit> zephyr kernel: run0: transfer complete: 56 bytes @ index 0
Oct  3 12:54:41 <kern.crit> zephyr kernel: run0: sending frame len=26/56 @ index 0
Oct  3 12:54:46 <kern.crit> zephyr kernel: run0: USB transfer error, USB_ERR_TIMEOUT
Oct  3 12:54:46 <kern.crit> zephyr kernel: run0: device timeout
Oct  3 12:54:46 <kern.crit> zephyr kernel: run0: cmdq_store=13
Oct  3 12:54:46 <kern.crit> zephyr kernel: run0: sending frame len=26/56 @ index 0
Oct  3 12:54:46 <kern.crit> zephyr kernel: run0: transfer complete: 56 bytes @ index 0
Oct  3 12:54:46 <kern.crit> zephyr kernel: run0: sending frame len=26/56 @ index 0
Oct  3 12:54:46 <kern.crit> zephyr kernel: run0: transfer complete: 56 bytes @ index 0
Oct  3 12:54:46 <kern.crit> zephyr kernel: run0: sending frame len=26/56 @ index 0
Oct  3 12:54:48 <kern.crit> zephyr kernel: run0: USB transfer error, USB_ERR_CANCELLED
Oct  3 12:54:53 <kern.crit> zephyr kernel: run0: firmware RT2870 ver. 0.33 loaded

I belive the USB_ERR_CANCELLED is when I downed the interface.
Comment 6 Jim Pirzyk freebsd_committer freebsd_triage 2019-10-08 00:20:19 UTC 
Here's another debug output, this time with all flags enabled:

Oct  7 19:14:05 <kern.crit> zephyr kernel: run0: rx done, actlen=48
Oct  7 19:14:06 <kern.crit> zephyr kernel: run0: debug reg 04000001
Oct  7 19:14:06 <kern.crit> zephyr kernel: run0: tx stat 0x400301a8
Oct  7 19:14:06 <kern.crit> zephyr kernel: run0: count=0
Oct  7 19:14:06 <kern.crit> zephyr kernel: run0: ridx=0
Oct  7 19:14:06 <kern.crit> zephyr kernel: run0: retrycnt=0 txcnt=0 success=0
Oct  7 19:14:06 <kern.crit> zephyr kernel: run0: ridx=7
Oct  7 19:14:07 <kern.crit> zephyr kernel: run0: rx done, actlen=680
Oct  7 19:14:07 <kern.crit> zephyr kernel: run0: received RT2860_RX_L2PAD frame
Oct  7 19:14:07 <kern.crit> zephyr kernel: run0: rx done, actlen=48
Oct  7 19:14:07 <kern.crit> zephyr kernel: run0: cmdq_store=12
Oct  7 19:14:07 <kern.crit> zephyr kernel: run0: cmdq_exec=12 pending=1
Oct  7 19:14:07 <kern.crit> zephyr kernel: run0: rx done, actlen=48
Oct  7 19:14:07 <kern.crit> zephyr kernel: run0: cmdq_store=13
Oct  7 19:14:07 <kern.crit> zephyr kernel: run0: cmdq_exec=13 pending=1
Oct  7 19:14:07 <kern.crit> zephyr kernel: run0: rx done, actlen=48
Oct  7 19:14:07 <kern.crit> zephyr kernel: run0: debug reg 04000001
Oct  7 19:14:07 <kern.crit> zephyr kernel: run0: tx stat 0x400301a8
Oct  7 19:14:07 <kern.crit> zephyr kernel: run0: count=0
Oct  7 19:14:07 <kern.crit> zephyr kernel: run0: ridx=0
Oct  7 19:14:07 <kern.crit> zephyr kernel: run0: retrycnt=0 txcnt=0 success=0
Oct  7 19:14:07 <kern.crit> zephyr kernel: run0: ridx=7
Oct  7 19:14:08 <kern.crit> zephyr kernel: run0: rx done, actlen=132
Oct  7 19:14:08 <kern.crit> zephyr kernel: run0: cmdq_store=14
Oct  7 19:14:08 <kern.crit> zephyr kernel: run0: cmdq_exec=14 pending=1
Oct  7 19:14:08 <kern.crit> zephyr kernel: run0: rx done, actlen=48
Oct  7 19:14:08 <kern.crit> zephyr kernel: run0: cmdq_store=15
Oct  7 19:14:08 <kern.crit> zephyr kernel: run0: cmdq_exec=15 pending=1
Oct  7 19:14:08 <kern.crit> zephyr kernel: run0: rx done, actlen=48
Oct  7 19:14:08 <kern.crit> zephyr kernel: run0: debug reg 04000001
Oct  7 19:14:08 <kern.crit> zephyr kernel: run0: tx stat 0x400301a8
Oct  7 19:14:08 <kern.crit> zephyr kernel: run0: count=0
Oct  7 19:14:08 <kern.crit> zephyr kernel: run0: ridx=0
Oct  7 19:14:08 <kern.crit> zephyr kernel: run0: retrycnt=0 txcnt=0 success=0
Oct  7 19:14:08 <kern.crit> zephyr kernel: run0: ridx=7
Oct  7 19:14:09 <kern.crit> zephyr kernel: run0: rx done, actlen=144
Oct  7 19:14:09 <kern.crit> zephyr kernel: run0: received RT2860_RX_L2PAD frame
Oct  7 19:14:09 <kern.crit> zephyr kernel: run0: rx done, actlen=48
Oct  7 19:14:09 <kern.crit> zephyr syslogd: last message repeated 1 times
Oct  7 19:14:09 <kern.crit> zephyr kernel: run0: debug reg 04000001
Oct  7 19:14:09 <kern.crit> zephyr kernel: run0: tx stat 0x400301a8
Oct  7 19:14:09 <kern.crit> zephyr kernel: run0: count=0
Oct  7 19:14:09 <kern.crit> zephyr kernel: run0: ridx=0
Oct  7 19:14:09 <kern.crit> zephyr kernel: run0: retrycnt=0 txcnt=0 success=0
Oct  7 19:14:09 <kern.crit> zephyr kernel: run0: ridx=7
Oct  7 19:14:10 <kern.crit> zephyr kernel: run0: rx done, actlen=632
Oct  7 19:14:10 <kern.crit> zephyr kernel: run0: received RT2860_RX_L2PAD frame
Oct  7 19:14:10 <kern.crit> zephyr kernel: run0: rx done, actlen=48
Oct  7 19:14:10 <kern.crit> zephyr kernel: run0: USB transfer error, USB_ERR_TIMEOUT
Oct  7 19:14:10 <kern.crit> zephyr kernel: run0: device timeout
Comment 7 Jim Pirzyk freebsd_committer freebsd_triage 2019-12-03 12:47:41 UTC 
FYI the card also times out on 12.1-RELEASE-p1.

I have swapped out the card for an Atheros AR9460 card and won't be able to do more testing.
Comment 8 Yuri Victorovich freebsd_committer freebsd_triage 2019-12-03 16:41:22 UTC 
(In reply to Jim Pirzyk from comment #7)

Does Atheros AR9460 work well?
Comment 9 Jim Pirzyk freebsd_committer freebsd_triage 2019-12-03 16:42:47 UTC 
(In reply to Yuri Victorovich from comment #8)

So far seems to.