Date: Sun, 21 Dec 2014 11:17:51 +0100 From: Matthias Apitz <guru@unixarea.de> To: Adrian Chadd <adrian@freebsd.org> Cc: "freebsd-wireless@freebsd.org" <freebsd-wireless@freebsd.org>, Nathan Whitehorn <nwhitehorn@freebsd.org> Subject: Re: Issues with urtwn Message-ID: <20141221101751.GA2138@unixarea.DDR.dd> In-Reply-To: <CAJ-Vmo=%2B%2BNXjKpEQ-=fh9AMgB_%2B_dxYCytG9A2GMqeE5LEKjdw@mail.gmail.com> References: <CAJ-Vmomhzsyn0k5Ym1=qm-LibJmW=8zb2LunYHNf4sSvWsP1=w@mail.gmail.com> <20141103054633.GA3258@unixarea.DDR.dd> <20141103095530.GA42402@unixarea.DDR.dd> <CAJ-Vmokn_Kqos%2B7HhN0EmB6JohD3g%2BVaXaqkhG-6%2BYZkgDoZFA@mail.gmail.com> <20141123163811.GA5739@unixarea.DDR.dd> <CAJ-VmomHguekQzfJ17gbK4_tTsuDPCfkDOjcTmviddDrmEEzoQ@mail.gmail.com> <20141219075339.GA1748@unixarea.DDR.dd> <CAJ-VmomFoRqnkKp0cyzC6sYKckXgrKQ%2B=nFJJKd18uqD2CMhDg@mail.gmail.com> <20141220105506.GA3170@unixarea.DDR.dd> <CAJ-Vmo=%2B%2BNXjKpEQ-=fh9AMgB_%2B_dxYCytG9A2GMqeE5LEKjdw@mail.gmail.com>
next in thread | previous in thread | raw e-mail | index | archive | help
--SUOF0GtieIMvvwua Content-Type: text/plain; charset=utf-8 Content-Disposition: inline Content-Transfer-Encoding: 8bit El día Saturday, December 20, 2014 a las 11:41:43AM -0800, Adrian Chadd escribió: > It's a race condition in the scan handling. :( > > When scan is cancelled (eg because something cancels it, or the state > transitions to IDLE or something because the VAP resets) then it > should be setting a flag to cancel things and the VAP should come out > of powerstate. > > However, there seems to be some conditions where the scan is coming > out of that loop because it's been aborted/stopped, so it's not > complete - but then it stays in powersave mode because whatever's > supposed to either change it (eg a state change, a received becaon, > TIM coming in, etc) doesn't follow. So it stays in power save. > > The driver routines are called without the comlock held, so that's a > small, narrow window for some state change to come through that > doesn't trigger the scan code to see the scan is canceled and "finish" > the scan (which would reset the vap powersave state.) > > I've added another cancel check in scan_task(). Please update this and > see what happens! > Hi Adrian, It works fine now, see the attached log. Thanks and ¡Feliz Navidad! matthias -- Matthias Apitz, guru@unixarea.de, http://www.unixarea.de/ +49-170-4527211 1989-2014: The Wall was torn down so that we go to war together again. El Muro ha sido derribado para que nos unimos en ir a la guerra otra vez. Diese Grenze wurde aufgehoben damit wir gemeinsam wieder in den Krieg ziehen. --SUOF0GtieIMvvwua Content-Type: text/plain; charset=utf-8 Content-Disposition: attachment; filename=messages Dec 21 10:15:41 unixarea kernel: ugen4.3: <vendor 0x7392> at usbus4 Dec 21 10:15:41 unixarea kernel: urtwn0: <vendor 0x7392 product 0x7811, class 0/0, rev 2.00/2.00, addr 3> on usbus4 Dec 21 10:15:41 unixarea kernel: urtwn0: MAC/BB RTL8188CUS, RF 6052 1T1R Dec 21 10:15:41 unixarea kernel: wlan0: Ethernet address: 80:1f:02:ee:16:37 Dec 21 10:15:42 unixarea wpa_supplicant[929]: Successfully initialized wpa_supplicant Dec 21 10:15:46 unixarea wpa_supplicant[930]: wlan0: Trying to associate with 00:13:f7:0d:08:48 (SSID='tarara' freq=2442 MHz) Dec 21 10:15:46 unixarea wpa_supplicant[930]: wlan0: Associated with 00:13:f7:0d:08:48 Dec 21 10:15:46 unixarea kernel: wlan0: link state changed to UP Dec 21 10:15:46 unixarea dhclient[995]: send_packet: No buffer space available Dec 21 10:15:51 unixarea wpa_supplicant[930]: wlan0: WPA: Key negotiation completed with 00:13:f7:0d:08:48 [PTK=CCMP GTK=CCMP] Dec 21 10:15:51 unixarea wpa_supplicant[930]: wlan0: CTRL-EVENT-CONNECTED - Connection to 00:13:f7:0d:08:48 completed [id=1 id_str=] Dec 21 10:15:52 unixarea dhclient: New IP Address (wlan0): 192.168.2.101 Dec 21 10:15:52 unixarea dhclient: New Subnet Mask (wlan0): 255.255.255.0 Dec 21 10:15:52 unixarea dhclient: New Broadcast Address (wlan0): 192.168.2.255 Dec 21 10:15:52 unixarea dhclient: New Routers (wlan0): 192.168.2.1 Dec 21 10:16:33 unixarea ipmon[518]: missed 1 ipf log entries: 0 1 Dec 21 10:16:33 unixarea ipmon[518]: 10:16:33.246627 wlan0 @0:3 p 192.168.2.101 -> 193.149.48.8 PR icmp len 20 84 icmp echo/0 K-S OUT Dec 21 10:17:02 unixarea ipmon[518]: 10:17:02.758277 wlan0 @0:14 p 192.168.2.101,32308 -> 178.254.11.41,80 PR tcp len 20 60 -S K-S OUT ... Dec 21 10:20:43 unixarea ipmon[518]: 10:20:43.551190 wlan0 @0:14 p 192.168.2.101,17676 -> 178.254.11.41,80 PR tcp len 20 60 -S K-S OUT Dec 21 10:20:46 unixarea kernel: wlan0: ieee80211_bg_scan: active scan, ticks 351546 duration 150 Dec 21 10:20:46 unixarea kernel: wlan0: scan_task: chan 7g -> 1g [active, dwell min 20ms max 150ms] Dec 21 10:20:46 unixarea kernel: wlan0: scan_task: stopped, [ticks 351715, dwell min 20 scanend 351698] Dec 21 10:20:46 unixarea kernel: wlan0: ieee80211_bg_scan: active scan, ticks 351751 duration 150 Dec 21 10:20:46 unixarea kernel: wlan0: scan_task: chan 7g -> 6g [active, dwell min 20ms max 150ms] Dec 21 10:20:46 unixarea kernel: wlan0: scan_task: stopped, [ticks 351919, dwell min 20 scanend 351902] Dec 21 10:20:46 unixarea kernel: wlan0: ieee80211_bg_scan: active scan, ticks 351956 duration 150 Dec 21 10:20:46 unixarea kernel: wlan0: scan_task: chan 7g -> 11g [active, dwell min 20ms max 150ms] Dec 21 10:20:46 unixarea kernel: wlan0: scan_task: stopped, [ticks 352124, dwell min 20 scanend 352107] Dec 21 10:20:46 unixarea kernel: wlan0: ieee80211_bg_scan: active scan, ticks 352161 duration 150 Dec 21 10:20:46 unixarea kernel: wlan0: scan_task: chan 7g -> 7g [active, dwell min 20ms max 150ms] Dec 21 10:20:46 unixarea kernel: [00:13:f7:0d:08:48] new probe_resp on chan 7 (bss chan 7) "tarara" rssi 84 Dec 21 10:20:46 unixarea kernel: [00:13:f7:0d:08:48] caps 0x431 bintval 100 erp 0x100 country [NL 1-13,20] Dec 21 10:20:46 unixarea kernel: [00:13:f7:0d:08:48] new probe_resp on chan 7 (bss chan 7) "tarara" rssi 84 Dec 21 10:20:46 unixarea kernel: [00:13:f7:0d:08:48] caps 0x431 bintval 100 erp 0x100 country [NL 1-13,20] Dec 21 10:20:46 unixarea kernel: wlan0: ieee80211_cancel_anyscan: cancel active scan Dec 21 10:20:46 unixarea kernel: wlan0: scan_task: done, [ticks 352209, dwell min 20 scanend 352311] Dec 21 10:20:46 unixarea ipmon[518]: 10:20:46.951522 wlan0 @0:14 p 192.168.2.101,42327 -> 178.254.11.41,80 PR tcp len 20 60 -S K-S OUT Dec 21 10:20:47 unixarea kernel: wlan0: ieee80211_bg_scan: active scan, ticks 352878 duration 150 Dec 21 10:20:47 unixarea kernel: wlan0: scan_task: chan 7g -> 2g [active, dwell min 20ms max 150ms] Dec 21 10:20:47 unixarea kernel: wlan0: scan_task: stopped, [ticks 353047, dwell min 20 scanend 353029] Dec 21 10:20:47 unixarea kernel: wlan0: ieee80211_bg_scan: active scan, ticks 353083 duration 150 Dec 21 10:20:47 unixarea kernel: wlan0: scan_task: chan 7g -> 3g [active, dwell min 20ms max 150ms] Dec 21 10:20:47 unixarea kernel: wlan0: scan_task: stopped, [ticks 353241, dwell min 20 scanend 353233] Dec 21 10:20:48 unixarea kernel: wlan0: ieee80211_bg_scan: active scan, ticks 353287 duration 150 Dec 21 10:20:48 unixarea kernel: wlan0: scan_task: chan 7g -> 4g [active, dwell min 20ms max 150ms] Dec 21 10:20:48 unixarea kernel: wlan0: scan_task: stopped, [ticks 353455, dwell min 20 scanend 353438] Dec 21 10:20:48 unixarea kernel: wlan0: ieee80211_bg_scan: active scan, ticks 353492 duration 150 Dec 21 10:20:48 unixarea kernel: wlan0: scan_task: chan 7g -> 5g [active, dwell min 20ms max 150ms] Dec 21 10:20:48 unixarea kernel: wlan0: scan_task: stopped, [ticks 353661, dwell min 20 scanend 353642] Dec 21 10:20:48 unixarea kernel: wlan0: ieee80211_bg_scan: active scan, ticks 353697 duration 150 Dec 21 10:20:48 unixarea kernel: wlan0: scan_task: chan 7g -> 8g [active, dwell min 20ms max 150ms] Dec 21 10:20:48 unixarea kernel: wlan0: scan_task: stopped, [ticks 353864, dwell min 20 scanend 353847] Dec 21 10:20:48 unixarea kernel: wlan0: ieee80211_bg_scan: active scan, ticks 353902 duration 150 Dec 21 10:20:48 unixarea kernel: wlan0: scan_task: chan 7g -> 9g [active, dwell min 20ms max 150ms] Dec 21 10:20:48 unixarea kernel: wlan0: scan_task: stopped, [ticks 354070, dwell min 20 scanend 354052] Dec 21 10:20:48 unixarea kernel: wlan0: ieee80211_bg_scan: active scan, ticks 354106 duration 150 Dec 21 10:20:48 unixarea kernel: wlan0: scan_task: chan 7g -> 10g [active, dwell min 20ms max 150ms] Dec 21 10:20:48 unixarea kernel: wlan0: scan_task: done, [ticks 354270, dwell min 20 scanend 354257] Dec 21 10:20:48 unixarea kernel: wlan0: notify scan done Dec 21 10:20:50 unixarea ipmon[518]: 10:20:50.331178 wlan0 @0:14 p 192.168.2.101,64467 -> 178.254.11.41,80 PR tcp len 20 60 -S K-S OUT ... Dec 21 10:25:47 unixarea ipmon[518]: 10:25:47.638609 wlan0 @0:14 p 192.168.2.101,58518 -> 178.254.11.41,80 PR tcp len 20 60 -S K-S OUT Dec 21 10:25:49 unixarea kernel: wlan0: ieee80211_bg_scan: active scan, ticks 654344 duration 150 Dec 21 10:25:49 unixarea kernel: wlan0: scan_task: chan 7g -> 1g [active, dwell min 20ms max 150ms] Dec 21 10:25:49 unixarea kernel: wlan0: scan_task: stopped, [ticks 654511, dwell min 20 scanend 654495] Dec 21 10:25:49 unixarea kernel: wlan0: ieee80211_bg_scan: active scan, ticks 654548 duration 150 Dec 21 10:25:49 unixarea kernel: wlan0: scan_task: chan 7g -> 6g [active, dwell min 20ms max 150ms] Dec 21 10:25:49 unixarea kernel: wlan0: scan_task: stopped, [ticks 654716, dwell min 20 scanend 654699] Dec 21 10:25:49 unixarea kernel: wlan0: ieee80211_bg_scan: active scan, ticks 654753 duration 150 Dec 21 10:25:49 unixarea kernel: wlan0: scan_task: chan 7g -> 11g [active, dwell min 20ms max 150ms] Dec 21 10:25:49 unixarea kernel: wlan0: scan_task: stopped, [ticks 654921, dwell min 20 scanend 654904] Dec 21 10:25:49 unixarea kernel: wlan0: ieee80211_bg_scan: active scan, ticks 654958 duration 150 Dec 21 10:25:49 unixarea kernel: wlan0: scan_task: chan 7g -> 7g [active, dwell min 20ms max 150ms] Dec 21 10:25:49 unixarea kernel: [00:13:f7:0d:08:48] new probe_resp on chan 7 (bss chan 7) "tarara" rssi 88 Dec 21 10:25:49 unixarea kernel: [00:13:f7:0d:08:48] caps 0x431 bintval 100 erp 0x100 country [NL 1-13,20] Dec 21 10:25:49 unixarea kernel: [00:13:f7:0d:08:48] new probe_resp on chan 7 (bss chan 7) "tarara" rssi 88 Dec 21 10:25:49 unixarea kernel: [00:13:f7:0d:08:48] caps 0x431 bintval 100 erp 0x100 country [NL 1-13,20] Dec 21 10:25:49 unixarea kernel: [00:13:f7:0d:08:48] new beacon on chan 7 (bss chan 7) "tarara" rssi 88 Dec 21 10:25:49 unixarea kernel: [00:13:f7:0d:08:48] caps 0x431 bintval 100 erp 0x100 country [NL 1-13,20] Dec 21 10:25:49 unixarea kernel: wlan0: ieee80211_add_scan: chan 7g min dwell met (655061 > 654983) Dec 21 10:25:49 unixarea kernel: wlan0: scan_task: chan 7g -> 2g [active, dwell min 20ms max 47ms] Dec 21 10:25:49 unixarea kernel: wlan0: scan_task: stopped, [ticks 655125, dwell min 20 scanend 655108] Dec 21 10:25:49 unixarea kernel: wlan0: ieee80211_bg_scan: active scan, ticks 655163 duration 150 Dec 21 10:25:49 unixarea kernel: wlan0: scan_task: chan 7g -> 3g [active, dwell min 20ms max 150ms] Dec 21 10:25:50 unixarea kernel: wlan0: scan_task: stopped, [ticks 655331, dwell min 20 scanend 655313] Dec 21 10:25:50 unixarea kernel: wlan0: ieee80211_bg_scan: active scan, ticks 655368 duration 150 Dec 21 10:25:50 unixarea kernel: wlan0: scan_task: chan 7g -> 4g [active, dwell min 20ms max 150ms] Dec 21 10:25:50 unixarea kernel: wlan0: scan_task: stopped, [ticks 655536, dwell min 20 scanend 655518] Dec 21 10:25:50 unixarea kernel: wlan0: ieee80211_bg_scan: active scan, ticks 655572 duration 150 Dec 21 10:25:50 unixarea kernel: wlan0: scan_task: chan 7g -> 5g [active, dwell min 20ms max 150ms] Dec 21 10:25:50 unixarea kernel: wlan0: scan_task: stopped, [ticks 655741, dwell min 20 scanend 655723] Dec 21 10:25:50 unixarea kernel: wlan0: ieee80211_bg_scan: active scan, ticks 655777 duration 150 Dec 21 10:25:50 unixarea kernel: wlan0: scan_task: chan 7g -> 8g [active, dwell min 20ms max 150ms] Dec 21 10:25:50 unixarea kernel: wlan0: scan_task: stopped, [ticks 655937, dwell min 20 scanend 655928] Dec 21 10:25:50 unixarea kernel: wlan0: ieee80211_bg_scan: active scan, ticks 655982 duration 150 Dec 21 10:25:50 unixarea kernel: wlan0: scan_task: chan 7g -> 9g [active, dwell min 20ms max 150ms] Dec 21 10:25:50 unixarea kernel: wlan0: scan_task: stopped, [ticks 656150, dwell min 20 scanend 656132] Dec 21 10:25:50 unixarea kernel: wlan0: ieee80211_bg_scan: active scan, ticks 656187 duration 150 Dec 21 10:25:50 unixarea kernel: wlan0: scan_task: chan 7g -> 10g [active, dwell min 20ms max 150ms] Dec 21 10:25:50 unixarea kernel: wlan0: ieee80211_cancel_anyscan: cancel active scan Dec 21 10:25:50 unixarea kernel: wlan0: scan_task: done, [ticks 656311, dwell min 20 scanend 656337] Dec 21 10:25:50 unixarea kernel: wlan0: notify scan done Dec 21 10:25:51 unixarea ipmon[518]: 10:25:51.040279 wlan0 @0:14 p 192.168.2.101,38698 -> 178.254.11.41,80 PR tcp len 20 60 -S K-S OUT ... --SUOF0GtieIMvvwua--
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20141221101751.GA2138>