From owner-freebsd-wireless@FreeBSD.ORG Sun Dec 21 10:18:00 2014 Return-Path: Delivered-To: freebsd-wireless@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [8.8.178.115]) (using TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)) (No client certificate requested) by hub.freebsd.org (Postfix) with ESMTPS id 2DBA9128; Sun, 21 Dec 2014 10:18:00 +0000 (UTC) Received: from ms-10.1blu.de (ms-10.1blu.de [178.254.4.101]) (using TLSv1 with cipher AES256-SHA (256/256 bits)) (Client did not present a certificate) by mx1.freebsd.org (Postfix) with ESMTPS id C9D3C3F16; Sun, 21 Dec 2014 10:17:58 +0000 (UTC) Received: from [93.104.9.34] (helo=unixarea.DDR.dd) by ms-10.1blu.de with esmtpsa (TLS1.0:DHE_RSA_AES_256_CBC_SHA1:32) (Exim 4.76) (envelope-from ) id 1Y2daF-0005xf-9U; Sun, 21 Dec 2014 11:17:55 +0100 Received: from unixarea.DDR.dd (localhost [127.0.0.1]) by unixarea.DDR.dd (8.14.9/8.14.3) with ESMTP id sBLAHqt4002169; Sun, 21 Dec 2014 11:17:52 +0100 (CET) (envelope-from guru@unixarea.de) Received: (from guru@localhost) by unixarea.DDR.dd (8.14.9/8.14.3/Submit) id sBLAHp1A002168; Sun, 21 Dec 2014 11:17:51 +0100 (CET) (envelope-from guru@unixarea.de) X-Authentication-Warning: unixarea.DDR.dd: guru set sender to guru@unixarea.de using -f Date: Sun, 21 Dec 2014 11:17:51 +0100 From: Matthias Apitz To: Adrian Chadd Subject: Re: Issues with urtwn Message-ID: <20141221101751.GA2138@unixarea.DDR.dd> Reply-To: Matthias Apitz References: <20141103054633.GA3258@unixarea.DDR.dd> <20141103095530.GA42402@unixarea.DDR.dd> <20141123163811.GA5739@unixarea.DDR.dd> <20141219075339.GA1748@unixarea.DDR.dd> <20141220105506.GA3170@unixarea.DDR.dd> MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="SUOF0GtieIMvvwua" Content-Disposition: inline Content-Transfer-Encoding: 8bit In-Reply-To: X-Operating-System: FreeBSD 11.0-CURRENT r269739 (i386) User-Agent: Mutt/1.5.23 (2014-03-12) X-Con-Id: 51246 X-Con-U: 0-guru X-Originating-IP: 93.104.9.34 Cc: "freebsd-wireless@freebsd.org" , Nathan Whitehorn X-BeenThere: freebsd-wireless@freebsd.org X-Mailman-Version: 2.1.18-1 Precedence: list List-Id: "Discussions of 802.11 stack, tools device driver development." List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Sun, 21 Dec 2014 10:18:00 -0000 --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: at usbus4 Dec 21 10:15:41 unixarea kernel: urtwn0: 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--