Finished: CALL FOR TESTERS Ralink wireless run(4) usb driver for FreeBSD

So, here we are. Sometimes it works, some other (I would say most), it needs unplug, replug. In the meanwhile, I finished installing KDE 4, so what I'm posting was done from an X terminal with root privileges. Please let me know if you need diagnostics from a console.

So, today I started the system, then in the terminal I launched ifconfig and the interfaces were present, but not connected to the network. So I extracted first the relevant run0 and wlan0 messages from dmesg:
Code: 
run0: <Ralink 11n Adapter, class 0/0, rev 2.00/1.01, addr 2> on usbus6
run0: MAC/BBP RT3071 (rev 0x021C), RF RT3022 (MIMO 2T2R), address 14:d6:4d:48:b1:cf
run0: firmware RT3071 loaded
wlan0: Ethernet address: 14:d6:4d:48:b1:cf
Then I launched wlandebug, waited some 20 secs, then stopped (wlandebug -i wlan0 0), as you indicated. The next dmesg grep was:
Code: 
run0: <Ralink 11n Adapter, class 0/0, rev 2.00/1.01, addr 2> on usbus6
run0: MAC/BBP RT3071 (rev 0x021C), RF RT3022 (MIMO 2T2R), address 14:d6:4d:48:b1:cf
run0: firmware RT3071 loaded
wlan0: Ethernet address: 14:d6:4d:48:b1:cf
wlan0: ieee80211_ioctl_scanreq: flags 0x52 duration 0x7fffffff mindwell 0 maxdwell 0 nssid 0
wlan0: start_scan_locked: active scan, duration 2147483647 mindwell 0 maxdwell 0, desired mode auto, append, nojoin, once
wlan0: scan set 1g, 6g, 11g, 7g, 2g, 3g, 4g, 5g, 8g, 9g, 10g dwell min 20ms max 200ms
wlan0: scan_task: chan  10g ->   1g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan   1g ->   6g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan   6g ->  11g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan  11g ->   7g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan   7g ->   2g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan   2g ->   3g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan   3g ->   4g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan   4g ->   5g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan   5g ->   8g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan   8g ->   9g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan   9g ->  10g [active, dwell min 20ms max 200ms]
wlan0: sta_pick_bss: no scan candidate
wlan0: scan_task: done, [ticks 322198, dwell min 20 scanend 2147803412]
wlan0: notify scan done
wlan0: ieee80211_ioctl_scanreq: flags 0x52 duration 0x7fffffff mindwell 0 maxdwell 0 nssid 0
wlan0: start_scan_locked: active scan, duration 2147483647 mindwell 0 maxdwell 0, desired mode auto, append, nojoin, once
wlan0: scan set 1g, 6g, 11g, 7g, 2g, 3g, 4g, 5g, 8g, 9g, 10g dwell min 20ms max 200ms
wlan0: scan_task: chan  10g ->   1g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan   1g ->   6g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan   6g ->  11g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan  11g ->   7g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan   7g ->   2g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan   2g ->   3g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan   3g ->   4g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan   4g ->   5g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan   5g ->   8g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan   8g ->   9g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan   9g ->  10g [active, dwell min 20ms max 200ms]
wlan0: sta_pick_bss: no scan candidate
wlan0: scan_task: done, [ticks 329632, dwell min 20 scanend 2147810846]
wlan0: notify scan done
wlan0: ieee80211_ioctl_scanreq: flags 0x52 duration 0x7fffffff mindwell 0 maxdwell 0 nssid 0
wlan0: start_scan_locked: active scan, duration 2147483647 mindwell 0 maxdwell 0, desired mode auto, append, nojoin, once
wlan0: scan set 1g, 6g, 11g, 7g, 2g, 3g, 4g, 5g, 8g, 9g, 10g dwell min 20ms max 200ms
wlan0: scan_task: chan  10g ->   1g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan   1g ->   6g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan   6g ->  11g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan  11g ->   7g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan   7g ->   2g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan   2g ->   3g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan   3g ->   4g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan   4g ->   5g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan   5g ->   8g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan   8g ->   9g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan   9g ->  10g [active, dwell min 20ms max 200ms]
wlan0: sta_pick_bss: no scan candidate
wlan0: scan_task: done, [ticks 337070, dwell min 20 scanend 2147818280]
wlan0: notify scan done
wlan0: ieee80211_ioctl_scanreq: flags 0x52 duration 0x7fffffff mindwell 0 maxdwell 0 nssid 0
wlan0: start_scan_locked: active scan, duration 2147483647 mindwell 0 maxdwell 0, desired mode auto, append, nojoin, once
wlan0: scan set 1g, 6g, 11g, 7g, 2g, 3g, 4g, 5g, 8g, 9g, 10g dwell min 20ms max 200ms
wlan0: scan_task: chan  10g ->   1g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan   1g ->   6g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan   6g ->  11g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan  11g ->   7g [active, dwell min 20ms max 200ms]
Finally, I unplugged and replugged the device, and did the dmesg grep again, with this result:
Code: 
run0: <Ralink 11n Adapter, class 0/0, rev 2.00/1.01, addr 2> on usbus6
run0: MAC/BBP RT3071 (rev 0x021C), RF RT3022 (MIMO 2T2R), address 14:d6:4d:48:b1:cf
run0: firmware RT3071 loaded
wlan0: Ethernet address: 14:d6:4d:48:b1:cf
wlan0: ieee80211_ioctl_scanreq: flags 0x52 duration 0x7fffffff mindwell 0 maxdwell 0 nssid 0
<... snip, same as before ...>
wlan0: scan_task: chan  10g ->   1g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan   1g ->   6g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan   6g ->  11g [active, dwell min 20ms max 200ms]
wlan0: scan_task: chan  11g ->   7g [active, dwell min 20ms max 200ms]
wlan0: ieee80211_new_state_locked: pending SCAN -> AUTH transition lost
wlan0: link state changed to UP
wlan0: link state changed to DOWN
wlan0: link state changed to UP
run0: at uhub6, port 1, addr 2 (disconnected)
wlan0: link state changed to DOWN
run0: <Ralink 11n Adapter, class 0/0, rev 2.00/1.01, addr 2> on usbus6
run0: MAC/BBP RT3071 (rev 0x021C), RF RT3022 (MIMO 2T2R), address 14:d6:4d:48:b1:cf
run0: firmware RT3071 loaded
wlan0: Ethernet address: 14:d6:4d:48:b1:cf
wlan0: link state changed to UP

/boot/loader.conf is now:
Code: 
if_run_load="YES"
runfw_load="YES"

wlan_wep_load="YES"
wlan_ccmp_load="YES"
wlan_tkip_load="YES"

nvidia_load="YES"
snd_hda_load="YES"
/etc/rc.conf also follows:
Code: 
# -- sysinstall generated deltas -- # Thu Oct 27 01:04:32 2011
# Created: Thu Oct 27 01:04:32 2011
# Enable network daemons for user convenience.
# Please make all changes to this file, not to /etc/defaults/rc.conf.
# This file now contains just the overrides from /etc/defaults/rc.conf.
keymap="us.international"
moused_enable="NO"

wlans_run0=wlan0
ifconfig_wlan0="WPA DHCP"

hald_enable="YES"
dbus_enable="YES"

kdm4_enable="YES"

Everything was done with the DWA 140. Apparently, the DWL G122 behaves similarly, but I didn't collect the same data on it. I hope this gives sufficient information. Please, let me know if I can be more precise.
 
I couldn't reproduce the problem on my laptop. Booted 5 times and worked on every time. Is it like booting works but not re-booting? I cannot re-boot my laptop. It stalls.

First, I forgot one wlandebug flag. When it is not working,# wlandebug -i wlan0 debugwait for 10-15 sec.# wlandebug -i wlan0 0% dmesg | grep wlan0:\ received\ beacon(Don't miss ":" after "wlan0".) Confirm (I guess) it doesn't return any thing.

Second, when it is not working (you can continue working, no need to re-boot after the above),# sysctl hw.usb.run.debug=15(If the above dmesg(8) returns something, set it to "10" instead of "15".) Wait for 10-15 sec.# sysctl hw.usb.run.debug=0% dmesg | grep run_ >> /file/you/choose(There is "_" after "run".) Post/attach the file.


Actually, this is wired. There should be another "changed to DOWN" before "UP".
Halberdier said:
Code: 
wlan0: link state changed to UP
wlan0: link state changed to DOWN
wlan0: link state changed to UP
Click to expand...
So, when it isn't working (again you can just continue on, no need to re-boot), % ifconfig wlan0and confirm "UP" and "RUNNING" flags are set, i.e.
Code: 
wlan0: flags=8843<[b]UP[/b], BROADCAST, [B]RUNNING[/B], SIMPLEX, MULTICAST> metric 0 mtu 1500


This
Halberdier said:
Code: 
wlans_run0=wlan0
Click to expand...
should be
Code: 
wlans_run0=[b]"[/b]wlan0[b]"[/b]
with quotation marks, just in case.


hint
You can issue all commands in KDE's terminal, and dmesg(8) prints out in it. Also, doing it with DWA-140 is sufficient, since RT2020 (DWL-G122) has a known issue.
 
It is the opposite, booting does not work, but now it doesn't require unplug/plug, the command
Code: 
wpa_supplicant -B -i wlan0 -c /etc/wpa_supplicant.conf
suffices. Then, on reboot, it works.

I did wlandebug ... debug, waited 20 secs, wlandebug ... 0, dmesg | grep wlan0:... and I confirm it didn't return anything, neither from root nor from normal user.

Then sysctl ...=15, wait 20 secs, sysctl ...=0, dmesg | grep... and the output file is this:
Code: 
run_tx_param: sending raw frame len=42 rate=2
run_bulk_tx_callbackN: sending frame len=42 xferlen=68 @ index 0
run_bulk_tx_callbackN: transfer complete: 68 bytes @ index 0
run_tx_param: sending raw frame len=42 rate=2
run_bulk_tx_callbackN: sending frame len=42 xferlen=68 @ index 0
run_bulk_tx_callbackN: transfer complete: 68 bytes @ index 0
run_tx_param: sending raw frame len=42 rate=2
run_bulk_tx_callbackN: sending frame len=42 xferlen=68 @ index 0
run_bulk_tx_callbackN: transfer complete: 68 bytes @ index 0
run_tx_param: sending raw frame len=42 rate=2
run_bulk_tx_callbackN: sending frame len=42 xferlen=68 @ index 0
run_bulk_tx_callbackN: transfer complete: 68 bytes @ index 0
run_tx_param: sending raw frame len=42 rate=2
run_bulk_tx_callbackN: sending frame len=42 xferlen=68 @ index 0
run_bulk_tx_callbackN: transfer complete: 68 bytes @ index 0
run_tx_param: sending raw frame len=42 rate=2
run_bulk_tx_callbackN: sending frame len=42 xferlen=68 @ index 0
run_bulk_tx_callbackN: transfer complete: 68 bytes @ index 0
run_tx_param: sending raw frame len=42 rate=2
run_bulk_tx_callbackN: sending frame len=42 xferlen=68 @ index 0
run_bulk_tx_callbackN: transfer complete: 68 bytes @ index 0
run_tx_param: sending raw frame len=42 rate=2
run_bulk_tx_callbackN: sending frame len=42 xferlen=68 @ index 0
run_bulk_tx_callbackN: transfer complete: 68 bytes @ index 0
run_tx_param: sending raw frame len=42 rate=2
run_bulk_tx_callbackN: sending frame len=42 xferlen=68 @ index 0
run_bulk_tx_callbackN: transfer complete: 68 bytes @ index 0
run_tx_param: sending raw frame len=42 rate=2
run_bulk_tx_callbackN: sending frame len=42 xferlen=68 @ index 0
run_bulk_tx_callbackN: transfer complete: 68 bytes @ index 0
run_tx_param: sending raw frame len=42 rate=2
run_bulk_tx_callbackN: sending frame len=42 xferlen=68 @ index 0
run_bulk_tx_callbackN: transfer complete: 68 bytes @ index 0
run_enable_tsf_sync: rvp_id=0 ic_opmode=1
run_tx_param: sending raw frame len=42 rate=2
run_bulk_tx_callbackN: sending frame len=42 xferlen=68 @ index 0
run_bulk_tx_callbackN: transfer complete: 68 bytes @ index 0
run_tx_param: sending raw frame len=42 rate=2
run_bulk_tx_callbackN: sending frame len=42 xferlen=68 @ index 0
run_bulk_tx_callbackN: transfer complete: 68 bytes @ index 0
run_tx_param: sending raw frame len=42 rate=2
run_bulk_tx_callbackN: sending frame len=42 xferlen=68 @ index 0
run_bulk_tx_callbackN: transfer complete: 68 bytes @ index 0
run_tx_param: sending raw frame len=42 rate=2
run_bulk_tx_callbackN: sending frame len=42 xferlen=68 @ index 0
run_bulk_tx_callbackN: transfer complete: 68 bytes @ index 0
run_tx_param: sending raw frame len=42 rate=2
run_bulk_tx_callbackN: sending frame len=42 xferlen=68 @ index 0
run_bulk_tx_callbackN: transfer complete: 68 bytes @ index 0
run_tx_param: sending raw frame len=42 rate=2
run_bulk_tx_callbackN: sending frame len=42 xferlen=68 @ index 0
run_bulk_tx_callbackN: transfer complete: 68 bytes @ index 0
run_tx_param: sending raw frame len=42 rate=2
run_bulk_tx_callbackN: sending frame len=42 xferlen=68 @ index 0
run_bulk_tx_callbackN: transfer complete: 68 bytes @ index 0
run_tx_param: sending raw frame len=42 rate=2
run_bulk_tx_callbackN: sending frame len=42 xferlen=68 @ index 0
run_bulk_tx_callbackN: transfer complete: 68 bytes @ index 0
run_tx_param: sending raw frame len=42 rate=2
run_bulk_tx_callbackN: sending frame len=42 xferlen=68 @ index 0
run_bulk_tx_callbackN: transfer complete: 68 bytes @ index 0
run_tx_param: sending raw frame len=42 rate=2
run_bulk_tx_callbackN: sending frame len=42 xferlen=68 @ index 0
run_bulk_tx_callbackN: transfer complete: 68 bytes @ index 0
run_tx_param: sending raw frame len=42 rate=2
run_bulk_tx_callbackN: sending frame len=42 xferlen=68 @ index 0
run_bulk_tx_callbackN: transfer complete: 68 bytes @ index 0
run_enable_tsf_sync: rvp_id=0 ic_opmode=1
run_tx_param: sending raw frame len=42 rate=2
run_bulk_tx_callbackN: sending frame len=42 xferlen=68 @ index 0
run_bulk_tx_callbackN: transfer complete: 68 bytes @ index 0
run_tx_param: sending raw frame len=42 rate=2
run_bulk_tx_callbackN: sending frame len=42 xferlen=68 @ index 0
run_bulk_tx_callbackN: transfer complete: 68 bytes @ index 0
run_tx_param: sending raw frame len=42 rate=2
run_bulk_tx_callbackN: sending frame len=42 xferlen=68 @ index 0
run_bulk_tx_callbackN: transfer complete: 68 bytes @ index 0
run_tx_param: sending raw frame len=42 rate=2
run_bulk_tx_callbackN: sending frame len=42 xferlen=68 @ index 0
run_bulk_tx_callbackN: transfer complete: 68 bytes @ index 0
run_tx_param: sending raw frame len=42 rate=2
run_bulk_tx_callbackN: sending frame len=42 xferlen=68 @ index 0
run_bulk_tx_callbackN: transfer complete: 68 bytes @ index 0
run_tx_param: sending raw frame len=42 rate=2
run_bulk_tx_callbackN: sending frame len=42 xferlen=68 @ index 0
run_bulk_tx_callbackN: transfer complete: 68 bytes @ index 0
run_tx_param: sending raw frame len=42 rate=2
run_bulk_tx_callbackN: sending frame len=42 xferlen=68 @ index 0
run_bulk_tx_callbackN: transfer complete: 68 bytes @ index 0
run_tx_param: sending raw frame len=42 rate=2
run_bulk_tx_callbackN: sending frame len=42 xferlen=68 @ index 0
run_bulk_tx_callbackN: transfer complete: 68 bytes @ index 0
run_tx_param: sending raw frame len=42 rate=2
run_bulk_tx_callbackN: sending frame len=42 xferlen=68 @ index 0
run_bulk_tx_callbackN: transfer complete: 68 bytes @ index 0
run_tx_param: sending raw frame len=42 rate=2
run_bulk_tx_callbackN: sending frame len=42 xferlen=68 @ index 0
run_bulk_tx_callbackN: transfer complete: 68 bytes @ index 0
run_tx_param: sending raw frame len=42 rate=2
run_bulk_tx_callbackN: sending frame len=42 xferlen=68 @ index 0
run_bulk_tx_callbackN: transfer complete: 68 bytes @ index 0
run_enable_tsf_sync: rvp_id=0 ic_opmode=1

wlans_run0=wlan0 : shame on me!!! Consider that I edited the file with emacs, so that it was highlighted in a stunning black among pale green and yellow words :D.

Until the next time.
 
It seems the driver is fine as long as the codes are properly executed, but something goes wrong during cold boot. As the result, the device will not properly be initiated.

usbd_do_request_flags() tends to fail. So that, it is put in a loop @if_run.c:1062
Code: 
static usb_error_t
run_do_request(struct run_softc *sc,
    struct usb_device_request *req, void *data)
{
	usb_error_t err;
	int ntries = 10;

	RUN_LOCK_ASSERT(sc, MA_OWNED);

	while (ntries--) {
		err = usbd_do_request_flags(sc->sc_udev, &sc->sc_mtx,
		    req, data, 0, NULL, 250 /* ms */);
		if (err == 0)
			break;
		DPRINTFN(1, "Control request failed, %s (retrying)\n",
		    usbd_errstr(err));
		run_delay(sc, 10);
	}
	return (err);
}
You can change that to
Code: 
static usb_error_t
run_do_request(struct run_softc *sc,
    struct usb_device_request *req, void *data)
{
	usb_error_t err;
	int ntries = 10;

	RUN_LOCK_ASSERT(sc, MA_OWNED);

	while (ntries--) {
		err = usbd_do_request_flags(sc->sc_udev, &sc->sc_mtx,
		    req, data, 0, NULL, 250 /* ms */);
		if (err == 0)
			[color="YellowGreen"]return (0);[/color]
		run_delay(sc, 10);
	}
	[color="YellowGreen"]device_printf(sc->sc_dev, "Control request failed, %s\n",
	    usbd_errstr(err));[/color]

	return (err);
}
If you see the message, that is the cause. Then, you may increase ntries as workaround.

Because I could not reproduce the problem, I am not sure if this fixes the issue. I will also keep eye on bug report might caused the issue. Until then, this is the best bet.
 
Hi,
I've got also a RT3070-based wifi usb, and have the same problem (doesn't work at boot).

I've modified the if_run.c file, but there's no message. How much do think i could increase the ntries variable? (Just for a test)
 
NicoM said:
Hi,
I've got also a RT3070-based wifi usb, and have the same problem (doesn't work at boot).

I've modified the if_run.c file, but there's no message. How much do think i could increase the ntries variable? (Just for a test)
Click to expand...
Well then, run_do_request() isn't the cause of the problem. (Changing ntries won't do anything.) This issue might be outside run(4).

What version are you using, 8.2-RELESE-p1, p2, or p3?
 
Hi,

Thank you for all this work! I'm on 8-2 RELEASE-p3. I'll post my dmesg soon. My wireless USB is an Edimax EW-7711UAn (support by run driver). It's weird because when I unplug then plug again it works. When it doesn't work, scanning won't detect any ssid.

And, when it works, sometimes, my ping command just kind of "freezes" (no results, even lost packets), it doesn't show anything, I have then to do Ctrl-C to stop it. Sometimes, doing [cmd=]wpa_supplicant -B -i wlan -c /etc/wpa_supplicant.conf[/cmd] works (without unplugging) but sometimes it doesn't.
 
Mine, after [cmd=]wpa_supplicant -B -i wlan -c /etc/wpa_supplicant.conf[/cmd] works regularly with no need to unplug, it just takes a bit to complete the dhcp handshake. I don't understand the p1, p2, p3 thing:

Code: 
# uname -aip
FreeBSD  8.2-RELEASE FreeBSD 8.2-RELEASE #0: Thu Feb 17 02:41:51 UTC 2011     root@mason.cse.buffalo.edu:/usr/obj/usr/src/sys/GENERIC  amd64 amd64 GENERIC
 
Hi,

My wireless USB is an DWA-125 on chip 3070. This device work as "Access point":
/etc/rc.conf
Code: 
wlans_run0="wlan0"
create_args_wlan0="wlanmode hostap ssid FreeBSD_AP channel 11"
ifconfig_wlan0="WPA inet 10.1.0.1 netmask 0xffffff00 up"
hostapd_enable="YES"
/etc/hostapd.conf
Code: 
interface=wlan0
logger_syslog=-1
logger_syslog_level=2
logger_stdout=-1
logger_stdout_level=2
debug=4
ctrl_interface=/var/run/hostapd
ctrl_interface_group=wheel
ssid=FreeBSD_AP
wpa=3
wpa_passphrase=verylongpassword
wpa_key_mgmt=WPA-PSK
wpa_pairwise=CCMP
uname -a
Code: 
FreeBSD gate.home 9.0-RC1 FreeBSD 9.0-RC1 #0: Mon Nov 14 21:27:57 VOLT 2011     
[email]root@gate.home[/email]:/usr/obj/usr/src/sys/KERNEL0  amd64
I plugin wireless USB, after some time, wireless net "freeze" with messages in logs.

Code: 
run0: device timeout 2
run0: device timeout 2

I have edited the source code /usr/src/sys/dev/usb/wlan/if_run.c line 2617:
Code: 
if (error == USB_ERR_TIMEOUT)
  device_printf(sc->sc_dev, "device timeout 1\n");
line 2817
Code: 
if (error == USB_ERR_TIMEOUT) {
  device_printf(sc->sc_dev, "device timeout 2\n");
and built kernel with debug symbols. As the result in logs:

View attachment log.txt
 
Excuse me, in my previous post

Code: 
run0: device timeout

And after change source code
...
Code: 
run0: device timeout 2
run0: device timeout 2
 
@Halberdier and @NicoM
The prime suspect of cold boot problem is variation in hz/tick, but the code looks OK i.e. I'll keep looking for bugs, but it may take for a while.

@NicoM
Ping problem is most likely encryption failure. When ping is not working, check if the device is still associated with% ifconfig wlan0(see "status"),
debug message with# wlandebug -i wlan0 crypto+assoc+auth, and# sysctl hw.usb.run.debug=1There should be error message like
Code: 
run_rx_frame: IVC error
(If you are using GENERIC kernel these cmd should work.) I am patching all encryption related glitch as responding usb/150189.

@StainlessRat
Try this patch
Code: 
diff --git a/dev/usb/wlan/if_run.c b/dev/usb/wlan/if_run.c
index 6f8608d..cca73d8 100644
--- a/dev/usb/wlan/if_run.c
+++ b/dev/usb/wlan/if_run.c
@@ -17,7 +17,7 @@
  */
 
 #include <sys/cdefs.h>
-__FBSDID("$FreeBSD: src/sys/dev/usb/wlan/if_run.c,v 1.25 2011/11/07 15:43:11 ed Exp $");
+__FBSDID("$FreeBSD$");
 
 /*-
  * Ralink Technology RT2700U/RT2800U/RT3000U chipset driver.
@@ -2718,7 +2718,6 @@ run_bulk_tx_callbackN(struct usb_xfer *xfer, usb_error_t error, unsigned int ind
 	struct run_endpoint_queue *pq = &sc->sc_epq[index];
 	struct mbuf *m;
 	usb_frlength_t size;
-	unsigned int len;
 	int actlen;
 	int sumlen;
 
@@ -2781,13 +2780,10 @@ tr_setup:
 			ieee80211_radiotap_tx(vap, m);
 		}
 
-		/* align end on a 4-bytes boundary */
-		len = (size + IEEE80211_CRC_LEN + m->m_pkthdr.len + 3) & ~3;
+		DPRINTFN(11, "sending frame len=%u  @ index %d\n",
+			m->m_pkthdr.len, index);
 
-		DPRINTFN(11, "sending frame len=%u xferlen=%u @ index %d\n",
-			m->m_pkthdr.len, len, index);
-
-		usbd_xfer_set_frame_len(xfer, 0, len);
+		usbd_xfer_set_frame_len(xfer, 0, size + m->m_pkthdr.len);
 		usbd_xfer_set_priv(xfer, data);
 
 		usbd_transfer_submit(xfer);
@@ -2932,6 +2928,15 @@ run_set_tx_desc(struct run_softc *sc, struct run_tx_data *data)
 
 	if (vap->iv_opmode != IEEE80211_M_STA && !IEEE80211_QOS_HAS_SEQ(wh))
 		txwi->xflags |= RT2860_TX_NSEQ;
+
+	/*
+	 * Align end on a 4-byte boundary, pad 8 bytes, and
+	 * be sure to zero those trailing bytes.
+	 */
+	uint8_t tail[11];
+	memset(tail, 0, 11);
+	m_append(m, ((m->m_pkthdr.len + 3) & ~3) - m->m_pkthdr.len + 8,
+	    (c_caddr_t)&tail);
 }
 
 /* This function must be called locked */
 
Thanks. The "ping" problem hasn't showed again yet, I'll try to get the messages next time they appear.

A friend lend me a D-Link DWA-140, and it doesn't have any of the issues of the Edimax EW-7711UAn (both with run driver). Cold boot, reboot, it always works (tried like 10 reboots and 10 cold boots). I wonder why the Edimax would have such issues.
 
SIFE said:
Does it support injection mode?
Click to expand...
There is no such mode. If you just want to shoot raw packets, you can do that though bpf. dhclient(8) sends packets in that way.

NicoM said:
A friend lend me a D-Link DWA-140, and it doesn't have any of the issues of the Edimax EW-7711UAn (both with run driver). Cold boot, reboot, it always works (tried like 10 reboots and 10 cold boots). I wonder why the Edimax would have such issues.
Click to expand...
There are different routine for different chipsets. Exactly, what chipset EW-7711UAn use? As far as I know, DWA-140 uses mac/rf == 3071/3022.

Actually, One committer is looking into pause/delay part of code. There might soon be a fix.
 
Hi
I test patch specified above. The error "run0: device timeout" doesn't appear.
But, wireless connection "freeze" with messages (attachment at the bottom)

"13:08:10" the network stoped
"13:08:26" i connect to server and run tcpdump ("13:09:09")
"13:09:14" has tried to lay out a tunnel to 10.1.0.2:5900
"13:09:26" break tcpdump.
No "ping"
Code: 
PING 10.1.0.2 (10.1.0.2): 56 data bytes
ping: sendto: Host is down
ping: sendto: Host is down

Code: 
arp -a
? (10.1.0.2) at (incomplete) on wlan0 expired [ethernet]
? (10.1.0.1) at f0:7d:68:62:ae:13 on wlan0 permanent [ethernet]
? (10.0.0.1) at 00:1c:f0:8b:4e:9e on vr0 permanent [ethernet]
? (192.168.1.2) at 70:71:bc:94:a5:ee on re0 permanent [ethernet]
 

Attachments

  • log1.txt
    9.4 KB · Views: 310
Oops! There is an extra ampersand. Sorry. Here is a patch to the previous patch.
Code: 
diff --git a/dev/usb/wlan/if_run.c b/dev/usb/wlan/if_run.c
index cca73d8..a2c795d 100644
--- a/dev/usb/wlan/if_run.c
+++ b/dev/usb/wlan/if_run.c
@@ -69,6 +69,7 @@ __FBSDID("$FreeBSD$");
 #include "usbdevs.h"
 
 #define USB_DEBUG_VAR run_debug
+#define USB_DEBUG
 #include <dev/usb/usb_debug.h>
 
 #include <dev/usb/wlan/if_runreg.h>
@@ -2936,7 +2937,7 @@ run_set_tx_desc(struct run_softc *sc, struct run_tx_data *data)
 	uint8_t tail[11];
 	memset(tail, 0, 11);
 	m_append(m, ((m->m_pkthdr.len + 3) & ~3) - m->m_pkthdr.len + 8,
-	    (c_caddr_t)&tail);
+	    (c_caddr_t)tail);
 }
 
 /* This function must be called locked */
or a patch to the stock driver (v. 1.25)
Code: 
diff --git a/dev/usb/wlan/if_run.c b/dev/usb/wlan/if_run.c
index 6f8608d..a2c795d 100644
--- a/dev/usb/wlan/if_run.c
+++ b/dev/usb/wlan/if_run.c
@@ -17,7 +17,7 @@
  */
 
 #include <sys/cdefs.h>
-__FBSDID("$FreeBSD: src/sys/dev/usb/wlan/if_run.c,v 1.25 2011/11/07 15:43:11 ed Exp $");
+__FBSDID("$FreeBSD$");
 
 /*-
  * Ralink Technology RT2700U/RT2800U/RT3000U chipset driver.
@@ -69,6 +69,7 @@ __FBSDID("$FreeBSD: src/sys/dev/usb/wlan/if_run.c,v 1.25 2011/11/07 15:43:11 ed
 #include "usbdevs.h"
 
 #define USB_DEBUG_VAR run_debug
+#define USB_DEBUG
 #include <dev/usb/usb_debug.h>
 
 #include <dev/usb/wlan/if_runreg.h>
@@ -2718,7 +2719,6 @@ run_bulk_tx_callbackN(struct usb_xfer *xfer, usb_error_t error, unsigned int ind
 	struct run_endpoint_queue *pq = &sc->sc_epq[index];
 	struct mbuf *m;
 	usb_frlength_t size;
-	unsigned int len;
 	int actlen;
 	int sumlen;
 
@@ -2781,13 +2781,10 @@ tr_setup:
 			ieee80211_radiotap_tx(vap, m);
 		}
 
-		/* align end on a 4-bytes boundary */
-		len = (size + IEEE80211_CRC_LEN + m->m_pkthdr.len + 3) & ~3;
+		DPRINTFN(11, "sending frame len=%u  @ index %d\n",
+			m->m_pkthdr.len, index);
 
-		DPRINTFN(11, "sending frame len=%u xferlen=%u @ index %d\n",
-			m->m_pkthdr.len, len, index);
-
-		usbd_xfer_set_frame_len(xfer, 0, len);
+		usbd_xfer_set_frame_len(xfer, 0, size + m->m_pkthdr.len);
 		usbd_xfer_set_priv(xfer, data);
 
 		usbd_transfer_submit(xfer);
@@ -2932,6 +2929,15 @@ run_set_tx_desc(struct run_softc *sc, struct run_tx_data *data)
 
 	if (vap->iv_opmode != IEEE80211_M_STA && !IEEE80211_QOS_HAS_SEQ(wh))
 		txwi->xflags |= RT2860_TX_NSEQ;
+
+	/*
+	 * Align end on a 4-byte boundary, pad 8 bytes, and
+	 * be sure to zero those trailing bytes.
+	 */
+	uint8_t tail[11];
+	memset(tail, 0, 11);
+	m_append(m, ((m->m_pkthdr.len + 3) & ~3) - m->m_pkthdr.len + 8,
+	    (c_caddr_t)tail);
 }
 
 /* This function must be called locked */
I also defined USB_DEBUG. You can set debug level on the fly even when you compile the driver separately from kernel with# sysctl hw.usb.run.debug=N(N = 1 is suficient for debugging this issue and won't make too much noise. N = 0 to turn it off.)
 
Hi.
My machine online 8-12 hours, 7 days on week, no more errors.
This a patch result for 1.23 version
Code: 
diff -u b/if_run.c a/if_run.c
--- b/if_run.c  2011-12-05 15:16:37.410924305 +0400
+++ a/if_run.c  2011-12-05 15:37:34.959926722 +0400
@@ -2718,7 +2718,6 @@
        struct run_endpoint_queue *pq = &sc->sc_epq[index];
        struct mbuf *m;
        usb_frlength_t size;
-       unsigned int len;
        int actlen;
        int sumlen;

@@ -2781,13 +2780,10 @@
                        ieee80211_radiotap_tx(vap, m);
                }

-               /* align end on a 4-bytes boundary */
-               len = (size + IEEE80211_CRC_LEN + m->m_pkthdr.len + 3) & ~3;
+               DPRINTFN(11, "sending frame len=%u  @ index %d\n",
+                       m->m_pkthdr.len, index);

-               DPRINTFN(11, "sending frame len=%u xferlen=%u @ index %d\n",
-                       m->m_pkthdr.len, len, index);
-
-               usbd_xfer_set_frame_len(xfer, 0, len);
+               usbd_xfer_set_frame_len(xfer, 0, size + m->m_pkthdr.len);
                usbd_xfer_set_priv(xfer, data);

                usbd_transfer_submit(xfer);
@@ -2932,6 +2928,15 @@

        if (vap->iv_opmode != IEEE80211_M_STA && !IEEE80211_QOS_HAS_SEQ(wh))
                txwi->xflags |= RT2860_TX_NSEQ;
+
+       /*
+        * Align end on a 4-byte boundary, pad 8 bytes, and
+        * be sure to zero those trailing bytes.
+        */
+       uint8_t tail[11];
+       memset(tail, 0, 11);
+       m_append(m, ((m->m_pkthdr.len + 3) & ~3) - m->m_pkthdr.len + 8,
+           (c_caddr_t)tail);
 }

 /* This function must be called locked */
Thank you very much ;)
 
Hi!

A have an usb wireless adapter:

ugen4.2: <802.11 g WLAN Ralink> at usbus4, cfg=0 md=HOST spd=HIGH (480Mbps) pwr=ON
run0: MAC/BBP RT3070 (rev 0x0201), RF RT2020 (MIMO 1T1R), address 54:e6:fc:8e:39:2f

I'm trying to use as access point with hostapd, but it's sending some packets and freeze. If I reconnect, working a bit and freeze again with these message:
run0: device timeout
run0: device timeout

I applied the patch above (if_run.c, recompiled), but the error is still apear.

Any suggestion?
 
I need more info. Please do followings and let me know what it says.

1) Add a line to /usr/src/sys/modules/usb/run/Makefile as below.
Code: 
SRCS=   opt_bus.h opt_usb.h device_if.h bus_if.h usb_if.h usbdevs.h \
        if_run.c

[color="Green"]+CFLAGS+= -DUSB_DEBUG
+[/color]
.include <bsd.kmod.mk>
2) recompile

3) set# sysctl hw.usb.run.debug=1

I'm wondering what this part is doing. How log does device work for before the timeout occurs?

If you are using a USB extension code, make sure to put it away from a power code or other higher voltage lines.
 
Here's the log:
Code: 
Jul 17 23:28:54 rozi kernel: run_newstate: INIT -> INIT
Jul 17 23:28:54 rozi kernel: run_newstate: INIT -> SCAN
Jul 17 23:28:54 rozi kernel: run_update_promisc_locked: entering promiscuous mode
Jul 17 23:28:57 rozi kernel: run_enable_tsf_sync: rvp_id=0 ic_opmode=4
Jul 17 23:28:57 rozi kernel: run_updateslot: cmdq_store=0
Jul 17 23:28:57 rozi kernel: run_wme_update: cmdq_store=1
Jul 17 23:28:57 rozi kernel: run_update_promisc_locked: leaving promiscuous mode
Jul 17 23:28:57 rozi kernel: run_newstate: SCAN -> RUN
Jul 17 23:28:57 rozi kernel: run_updateslot: cmdq_store=2
Jul 17 23:28:57 rozi kernel: run_enable_tsf_sync: rvp_id=0 ic_opmode=4
Jul 17 23:29:04 rozi kernel: run_newassoc: cmdq_store=3
Jul 17 23:29:04 rozi kernel: run_newassoc: new assoc isnew=1 associd=c001 addr=00:26:37:66:d2:8e
Jul 17 23:29:04 rozi kernel: run_newassoc: rate=0x82 ridx=0 ctl_ridx=0
Jul 17 23:29:04 rozi kernel: run_newassoc: rate=0x84 ridx=1 ctl_ridx=1
Jul 17 23:29:04 rozi kernel: run_newassoc: rate=0x8b ridx=2 ctl_ridx=2
Jul 17 23:29:04 rozi kernel: run_newassoc: rate=0x0c ridx=4 ctl_ridx=4
Jul 17 23:29:04 rozi kernel: run_newassoc: rate=0x12 ridx=5 ctl_ridx=4
Jul 17 23:29:04 rozi kernel: run_newassoc: rate=0x96 ridx=3 ctl_ridx=3
Jul 17 23:29:04 rozi kernel: run_newassoc: rate=0x18 ridx=6 ctl_ridx=6
Jul 17 23:29:04 rozi kernel: run_newassoc: rate=0x24 ridx=7 ctl_ridx=6
Jul 17 23:29:04 rozi kernel: run_newassoc: rate=0x30 ridx=8 ctl_ridx=8
Jul 17 23:29:04 rozi kernel: run_newassoc: rate=0x48 ridx=9 ctl_ridx=8
Jul 17 23:29:04 rozi kernel: run_newassoc: rate=0x60 ridx=10 ctl_ridx=8
Jul 17 23:29:04 rozi kernel: run_newassoc: rate=0x6c ridx=11 ctl_ridx=8
Jul 17 23:29:04 rozi kernel: run_newassoc: rate=2, mgmt_ridx=0
Jul 17 23:29:04 rozi kernel: run_update_beacon: cmdq_store=4
Jul 17 23:29:04 rozi kernel: run_wme_update: cmdq_store=5
Jul 17 23:29:04 rozi kernel: run_update_beacon: cmdq_store=6
Jul 17 23:29:04 rozi kernel: run_update_beacon: cmdq_store=7
Jul 17 23:29:04 rozi kernel: run_update_beacon: cmdq_store=8
Jul 17 23:29:04 rozi kernel: run_update_beacon: cmdq_store=9
Jul 17 23:29:12 rozi kernel: run_update_beacon: cmdq_store=10
Jul 17 23:29:12 rozi kernel: run_update_beacon: cmdq_store=11
Jul 17 23:29:14 rozi kernel: run_update_beacon: cmdq_store=12
Jul 17 23:29:14 rozi kernel: run_update_beacon: cmdq_store=13
Jul 17 23:29:52 rozi kernel: run_update_beacon: cmdq_store=1
Jul 17 23:29:52 rozi kernel: run_update_beacon: cmdq_store=2
Jul 17 23:30:03 rozi kernel: run_update_beacon: cmdq_store=6
Jul 17 23:30:03 rozi kernel: run_update_beacon: cmdq_store=7
Jul 17 23:30:04 rozi kernel: run_update_beacon: cmdq_store=8
Jul 17 23:30:04 rozi kernel: run_update_beacon: cmdq_store=9
Jul 17 23:30:05 rozi kernel: run_update_beacon: cmdq_store=10
Jul 17 23:30:05 rozi kernel: run_update_beacon: cmdq_store=11
Jul 17 23:30:05 rozi kernel: run_update_beacon: cmdq_store=12
Jul 17 23:30:05 rozi kernel: run_update_beacon: cmdq_store=13
Jul 17 23:30:11 rozi kernel: run_update_beacon: cmdq_store=2
Jul 17 23:30:11 rozi kernel: run_update_beacon: cmdq_store=3
Jul 17 23:30:16 rozi kernel: run_bulk_tx_callbackN: USB transfer error, USB_ERR_TIMEOUT
Jul 17 23:30:16 rozi kernel: run0: device timeout
Jul 17 23:30:16 rozi kernel: run_bulk_tx_callbackN: cmdq_store=4
Jul 17 23:30:18 rozi kernel: run_update_beacon: cmdq_store=5
Jul 17 23:30:18 rozi kernel: run_update_beacon: cmdq_store=6
Jul 17 23:30:18 rozi kernel: run_update_beacon: cmdq_store=7
Jul 17 23:30:18 rozi kernel: run_update_beacon: cmdq_store=8
Jul 17 23:30:34 rozi kernel: run_bulk_tx_callbackN: USB transfer error, USB_ERR_TIMEOUT
Jul 17 23:30:34 rozi kernel: run0: device timeout
Jul 17 23:30:34 rozi kernel: run_bulk_tx_callbackN: cmdq_store=9
Jul 17 23:30:39 rozi kernel: run_bulk_tx_callbackN: USB transfer error, USB_ERR_TIMEOUT
Jul 17 23:30:39 rozi kernel: run0: device timeout
Jul 17 23:30:39 rozi kernel: run_bulk_tx_callbackN: cmdq_store=10
Jul 17 23:30:43 rozi kernel: run_update_beacon: cmdq_store=11
Jul 17 23:30:44 rozi kernel: run_update_beacon: cmdq_store=12
Jul 17 23:30:48 rozi kernel: run_bulk_tx_callbackN: USB transfer error, USB_ERR_TIMEOUT
Jul 17 23:30:48 rozi kernel: run0: device timeout
Jul 17 23:30:48 rozi kernel: run_bulk_tx_callbackN: cmdq_store=13
Jul 17 23:30:49 rozi kernel: run_update_beacon: cmdq_store=14
Jul 17 23:30:49 rozi kernel: run_update_beacon: cmdq_store=15
Jul 17 23:30:53 rozi kernel: run_bulk_tx_callbackN: USB transfer error, USB_ERR_TIMEOUT
Jul 17 23:30:53 rozi kernel: run0: device timeout
Jul 17 23:30:53 rozi kernel: run_bulk_tx_callbackN: cmdq_store=0
Jul 17 23:30:58 rozi kernel: run_bulk_tx_callbackN: USB transfer error, USB_ERR_TIMEOUT
Jul 17 23:30:58 rozi kernel: run0: device timeout
Jul 17 23:30:58 rozi kernel: run_bulk_tx_callbackN: cmdq_store=1
Jul 17 23:31:01 rozi kernel: run_update_beacon: cmdq_store=2
Jul 17 23:31:01 rozi kernel: run_update_beacon: cmdq_store=3
Jul 17 23:31:03 rozi kernel: run_bulk_tx_callbackN: USB transfer error, USB_ERR_TIMEOUT
Jul 17 23:31:03 rozi kernel: run0: device timeout
Jul 17 23:31:03 rozi kernel: run_bulk_tx_callbackN: cmdq_store=4
Jul 17 23:31:07 rozi kernel: run_bulk_tx_callbackN: USB transfer error, USB_ERR_TIMEOUT
Jul 17 23:31:07 rozi kernel: run0: device timeout
Jul 17 23:31:07 rozi kernel: run_bulk_tx_callbackN: cmdq_store=5
Jul 17 23:31:17 rozi kernel: run_bulk_tx_callbackN: USB transfer error, USB_ERR_TIMEOUT
Jul 17 23:31:17 rozi kernel: run0: device timeout
Jul 17 23:31:17 rozi kernel: run_bulk_tx_callbackN: cmdq_store=6
Jul 17 23:31:22 rozi kernel: run_bulk_tx_callbackN: USB transfer error, USB_ERR_TIMEOUT
Jul 17 23:31:22 rozi kernel: run0: device timeout
Jul 17 23:31:22 rozi kernel: run_bulk_tx_callbackN: cmdq_store=7
Jul 17 23:31:26 rozi kernel: run_update_beacon: cmdq_store=8
Jul 17 23:31:26 rozi kernel: run_update_beacon: cmdq_store=9
Jul 17 23:31:31 rozi kernel: run_bulk_tx_callbackN: USB transfer error, USB_ERR_TIMEOUT
Jul 17 23:31:31 rozi kernel: run0: device timeout
Jul 17 23:31:31 rozi kernel: run_bulk_tx_callbackN: cmdq_store=10
Jul 17 23:32:07 rozi kernel: run_bulk_tx_callbackN: USB transfer error, USB_ERR_TIMEOUT
Jul 17 23:32:07 rozi kernel: run0: device timeout
Jul 17 23:32:07 rozi kernel: run_bulk_tx_callbackN: cmdq_store=11
Jul 17 23:32:14 rozi kernel: run_update_beacon: cmdq_store=12
Jul 17 23:32:14 rozi kernel: run_update_beacon: cmdq_store=13
Jul 17 23:32:42 rozi kernel: run_bulk_tx_callbackN: USB transfer error, USB_ERR_TIMEOUT
Jul 17 23:32:42 rozi kernel: run0: device timeout
Jul 17 23:32:42 rozi kernel: run_bulk_tx_callbackN: cmdq_store=14
Jul 17 23:32:47 rozi kernel: run_bulk_tx_callbackN: USB transfer error, USB_ERR_TIMEOUT
Jul 17 23:32:47 rozi kernel: run0: device timeout
Jul 17 23:32:47 rozi kernel: run_bulk_tx_callbackN: cmdq_store=15
Jul 17 23:32:52 rozi kernel: run_bulk_tx_callbackN: USB transfer error, USB_ERR_TIMEOUT
Jul 17 23:32:52 rozi kernel: run0: device timeout
Jul 17 23:32:52 rozi kernel: run_bulk_tx_callbackN: cmdq_store=0

Between 23:29:04 - 23:30:11 worked fine. I searched in a google, and start downloading the first result. The most part of the data was received (about 80%), but after it (23:30:16 rozi kernel: run0: device timeout) the browser stopped to download the rest.
 
Can you check if the device is still sending beacons after timeout occurs, i.e
1) a station can still see the ap,
2) a LED on the USB device is still blinking at the same rate as beacon tx (default is 10 times/sec.), or
3) capture a beacon.

Because there are multiple beacon update per second, the hardware might read beacon buffer area while driver is writing on it. When the hardware gets one corrupted descriptor, tx could stuck.
 
I will check the blinking speed at night.

I connecting to the ap with my cellphone. After the freeze, the phone can reconnect later (it's need 2 minutes for hostapd releasing the sid, but if I restarting the hostapd the phone can connect immediatly). The LED is still blinking, but I never tested the rate.

How can I capture the beacon?
 
These are missing from the previous post:

FreeBSD 9.0-RELEASE #0: Tue Jan 3 07:15:25 UTC 2012

Jul 18 23:20:38 rozi kernel: run0: MAC/BBP RT3070 (rev 0x0201), RF RT2020 (MIMO 1T1R), address 54:e6:fc:8e:39:2f
Jul 18 23:20:38 rozi kernel: run0: firmware RT2870 loaded

A new log's file attached.


When timeout happens:
- another device can see the ap, but can't connect (ap is not responding)
- the wifi's led is blinking with the same speed
 

Attachments

  • log.txt
    11.1 KB · Views: 358
Thanks for the more log.

So, this is what happening. When timeout happens,
* stations can still see the AP, but cannot connect;
* without touching the AP (no power down or no command issued on the AP) just waiting for several minutes, station can reconnect. (mmm... This puzzles me more.)

Then, attached workaround might work. All patches have been applied, just replace if_run.c and recompile.
 

Attachments

  • if_run.c.bz2
    27.1 KB · Views: 215
You must log in or register to reply here.
Back
Top