From owner-freebsd-bugs@FreeBSD.ORG Thu Oct 24 06:00:01 2013 Return-Path: Delivered-To: freebsd-bugs@smarthost.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [8.8.178.115]) (using TLSv1 with cipher ADH-AES256-SHA (256/256 bits)) (No client certificate requested) by hub.freebsd.org (Postfix) with ESMTP id E60BACA for ; Thu, 24 Oct 2013 06:00:00 +0000 (UTC) (envelope-from gnats@FreeBSD.org) Received: from freefall.freebsd.org (freefall.freebsd.org [IPv6:2001:1900:2254:206c::16:87]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by mx1.freebsd.org (Postfix) with ESMTPS id C72732B37 for ; Thu, 24 Oct 2013 06:00:00 +0000 (UTC) Received: from freefall.freebsd.org (localhost [127.0.0.1]) by freefall.freebsd.org (8.14.7/8.14.7) with ESMTP id r9O6000V063499 for ; Thu, 24 Oct 2013 06:00:00 GMT (envelope-from gnats@freefall.freebsd.org) Received: (from gnats@localhost) by freefall.freebsd.org (8.14.7/8.14.7/Submit) id r9O600WS063498; Thu, 24 Oct 2013 06:00:00 GMT (envelope-from gnats) Resent-Date: Thu, 24 Oct 2013 06:00:00 GMT Resent-Message-Id: <201310240600.r9O600WS063498@freefall.freebsd.org> Resent-From: FreeBSD-gnats-submit@FreeBSD.org (GNATS Filer) Resent-To: freebsd-bugs@FreeBSD.org Resent-Reply-To: FreeBSD-gnats-submit@FreeBSD.org, adrian chadd Received: from mx1.freebsd.org (mx1.freebsd.org [8.8.178.115]) (using TLSv1 with cipher ADH-AES256-SHA (256/256 bits)) (No client certificate requested) by hub.freebsd.org (Postfix) with ESMTP id B2AADEDD for ; Thu, 24 Oct 2013 05:54:33 +0000 (UTC) (envelope-from nobody@FreeBSD.org) Received: from oldred.freebsd.org (oldred.freebsd.org [8.8.178.121]) (using TLSv1 with cipher DHE-RSA-AES256-SHA (256/256 bits)) (No client certificate requested) by mx1.freebsd.org (Postfix) with ESMTPS id A0FFC2B03 for ; Thu, 24 Oct 2013 05:54:33 +0000 (UTC) Received: from oldred.freebsd.org ([127.0.1.6]) by oldred.freebsd.org (8.14.5/8.14.7) with ESMTP id r9O5sXrI089573 for ; Thu, 24 Oct 2013 05:54:33 GMT (envelope-from nobody@oldred.freebsd.org) Received: (from nobody@localhost) by oldred.freebsd.org (8.14.5/8.14.5/Submit) id r9O5sXU7089562; Thu, 24 Oct 2013 05:54:33 GMT (envelope-from nobody) Message-Id: <201310240554.r9O5sXU7089562@oldred.freebsd.org> Date: Thu, 24 Oct 2013 05:54:33 GMT From: adrian chadd To: freebsd-gnats-submit@FreeBSD.org X-Send-Pr-Version: www-3.1 Subject: kern/183260: [iwn] [4965] transmit seems to fail after a while X-BeenThere: freebsd-bugs@freebsd.org X-Mailman-Version: 2.1.14 Precedence: list List-Id: Bug reports List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Thu, 24 Oct 2013 06:00:01 -0000 >Number: 183260 >Category: kern >Synopsis: [iwn] [4965] transmit seems to fail after a while >Confidential: no >Severity: non-critical >Priority: low >Responsible: freebsd-bugs >State: open >Quarter: >Keywords: >Date-Required: >Class: sw-bug >Submitter-Id: current-users >Arrival-Date: Thu Oct 24 06:00:00 UTC 2013 >Closed-Date: >Last-Modified: >Originator: adrian chadd >Release: -HEAD >Organization: >Environment: >Description: Transmit seems to fail after a while. Here's the output of tx_done whilst transmit is failing: Oct 23 15:46:26 lucy kernel: iwn_tx_data: qid 0 idx 180 len 52 nsegs 2 Oct 23 15:46:26 lucy kernel: iwn4965_tx_done: qid 0 idx 180 retries 0 nkill 0 rate 8000 duration 0 status 8b Oct 23 15:46:27 lucy kernel: iwn_tx_data: qid 0 idx 181 len 52 nsegs 2 Oct 23 15:46:27 lucy kernel: iwn4965_tx_done: qid 0 idx 181 retries 0 nkill 0 rate 8000 duration 0 status 8b Oct 23 15:46:28 lucy kernel: iwn_tx_data: qid 0 idx 182 len 52 nsegs 2 Oct 23 15:46:28 lucy kernel: iwn4965_tx_done: qid 0 idx 182 retries 0 nkill 0 rate 8000 duration 0 status 8b Oct 23 15:46:29 lucy kernel: wlan0: [f8:e4:fb:1a:49:79] AMRR: current rate 15, txcnt=11, retrycnt=0 . note that AMRR thinks things are A-OK. Oct 23 15:46:29 lucy kernel: iwn_tx_data: qid 0 idx 183 len 52 nsegs 2 Oct 23 15:46:29 lucy kernel: iwn4965_tx_done: qid 0 idx 183 retries 0 nkill 0 rate 8000 duration 0 status 8b Oct 23 15:46:30 lucy kernel: iwn_tx_data: qid 0 idx 184 len 52 nsegs 2 Oct 23 15:46:30 lucy kernel: iwn4965_tx_done: qid 0 idx 184 retries 0 nkill 0 rate 8000 duration 0 status 8b Oct 23 15:46:31 lucy kernel: iwn_tx_data: qid 0 idx 185 len 52 nsegs 2 Oct 23 15:46:31 lucy kernel: iwn4965_tx_done: qid 0 idx 185 retries 0 nkill 0 rate 8000 duration 0 status 8b Oct 23 15:46:32 lucy kernel: iwn_tx_data: qid 0 idx 186 len 52 nsegs 2 Oct 23 15:46:32 lucy kernel: iwn4965_tx_done: qid 0 idx 186 retries 0 nkill 0 rate 8000 duration 0 status 8b Oct 23 15:46:33 lucy kernel: iwn_tx_data: qid 0 idx 187 len 52 nsegs 2 Oct 23 15:46:33 lucy kernel: iwn4965_tx_done: qid 0 idx 187 retries 0 nkill 0 rate 8000 duration 0 status 8b Oct 23 15:46:34 lucy kernel: iwn_tx_data: qid 0 idx 188 len 52 nsegs 2 Oct 23 15:46:34 lucy kernel: iwn4965_tx_done: qid 0 idx 188 retries 0 nkill 0 rate 8000 duration 0 status 8b Oct 23 15:46:38 lucy kernel: iwn_tx_data: qid 0 idx 189 len 52 nsegs 2 Oct 23 15:46:38 lucy kernel: iwn4965_tx_done: qid 0 idx 189 retries 0 nkill 0 rate 8000 duration 0 status 8b Oct 23 15:46:39 lucy kernel: iwn_tx_data: qid 0 idx 190 len 52 nsegs 2 Oct 23 15:46:39 lucy kernel: iwn4965_tx_done: qid 0 idx 190 retries 0 nkill 0 rate 8000 duration 0 status 8b Oct 23 15:46:40 lucy kernel: iwn_tx_data: qid 0 idx 191 len 52 nsegs 2 Oct 23 15:46:40 lucy kernel: iwn4965_tx_done: qid 0 idx 191 retries 0 nkill 0 rate 8000 duration 0 status 8b Oct 23 15:46:41 lucy kernel: iwn_tx_data: qid 0 idx 192 len 52 nsegs 2 Oct 23 15:46:41 lucy kernel: iwn4965_tx_done: qid 0 idx 192 retries 0 nkill 0 rate 8000 duration 0 status 8b Oct 23 15:46:42 lucy kernel: iwn_tx_data: qid 0 idx 193 len 52 nsegs 2 Oct 23 15:46:42 lucy kernel: iwn4965_tx_done: qid 0 idx 193 retries 0 nkill 0 rate 8000 duration 0 status 8b Oct 23 15:46:43 lucy kernel: wlan0: [f8:e4:fb:1a:49:79] AMRR: current rate 15, txcnt=11, retrycnt=0 Oct 23 15:46:43 lucy kernel: iwn_tx_data: qid 0 idx 194 len 52 nsegs 2 Oct 23 15:46:43 lucy kernel: iwn4965_tx_done: qid 0 idx 194 retries 0 nkill 0 rate 8000 duration 0 status 8b Oct 23 15:46:44 lucy kernel: iwn_tx_data: qid 0 idx 195 len 52 nsegs 2 Oct 23 15:46:44 lucy kernel: iwn4965_tx_done: qid 0 idx 195 retries 0 nkill 0 rate 8000 duration 0 status 8b Oct 23 15:46:46 lucy kernel: iwn_tx_data: qid 0 idx 196 len 52 nsegs 2 Oct 23 15:46:46 lucy kernel: iwn4965_tx_done: qid 0 idx 196 retries 0 nkill 0 rate 8000 duration 0 status 8b Oct 23 15:46:46 lucy kernel: iwn_tx_data: qid 0 idx 197 len 52 nsegs 2 Oct 23 15:46:46 lucy kernel: iwn4965_tx_done: qid 0 idx 197 retries 0 nkill 0 rate 8000 duration 0 status 8b Oct 23 15:46:47 lucy kernel: iwn_tx_data: qid 0 idx 198 len 52 nsegs 2 Oct 23 15:46:47 lucy kernel: iwn4965_tx_done: qid 0 idx 198 retries 0 nkill 0 rate 8000 duration 0 status 8b Oct 23 15:46:48 lucy kernel: iwn_tx_data: qid 0 idx 199 len 52 nsegs 2 Oct 23 15:46:48 lucy kernel: iwn4965_tx_done: qid 0 idx 199 retries 0 nkill 0 rate 8000 duration 0 status 8b Oct 23 15:46:49 lucy kernel: iwn_tx_data: qid 0 idx 200 len 52 nsegs 2 Oct 23 15:46:49 lucy kernel: iwn4965_tx_done: qid 0 idx 200 retries 0 nkill 0 rate 8000 duration 0 status 8b ^C adrian@lucy:~/work/freebsd/ath/head/src/sys/modules]> tail -f /var/log/all.log Oct 23 15:49:00 lucy kernel: wlan0: [00:1f:3b:27:ae:88] amrr_node_init: non-11n node Oct 23 15:49:00 lucy kernel: wlan0: [00:1f:3b:27:ae:88] AMRR: nrates=0, initial rate 0 Oct 23 15:49:00 lucy kernel: iwn4965_tx_done: qid 3 idx 9 retries 0 nkill 0 rate 420a duration 746 status 3201 Oct 23 15:49:00 lucy kernel: wlan0: link state changed to DOWN Oct 23 15:49:00 lucy dhclient[2501]: My address (192.168.1.11) was deleted, dhclient exiting Oct 23 15:49:00 lucy kernel: Oct 23 15:49:00 lucy dhclient[2501]: My address (192.168.1.11) was deleted, dhclient exiting Oct 23 15:49:00 lucy dhclient[2461]: connection closed Oct 23 15:49:00 lucy kernel: Oct 23 15:49:00 lucy dhclient[2461]: connection closed Oct 23 15:49:00 lucy dhclient[2461]: exiting. Oct 23 15:49:00 lucy kernel: Oct 23 15:49:00 lucy dhclient[2461]: exiting. Oct 23 15:49:03 lucy kernel: temperature 318K/45C . and here's where I re-started wpa_supplicant. Things work fine now. Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 1 status 1 Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 6 status 1 Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 11 status 1 Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 7 status 1 Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 13 status 1 Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 52 status 1 Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 56 status 1 Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 60 status 1 Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 64 status 1 Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 36 status 1 Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 40 status 1 Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 44 status 1 Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 48 status 1 Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 2 status 1 Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 3 status 1 Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 4 status 1 Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 5 status 1 Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 8 status 1 Oct 23 15:49:04 lucy kernel: iwn_notif_intr: scanning channel 9 status 1 Oct 23 15:49:04 lucy kernel: iwn_notif_intr: scanning channel 10 status 1 Oct 23 15:49:04 lucy kernel: iwn_notif_intr: scanning channel 12 status 1 Oct 23 15:49:04 lucy kernel: iwn_notif_intr: scanning channel 149 status 1 Oct 23 15:49:04 lucy kernel: iwn_notif_intr: scanning channel 153 status 1 Oct 23 15:49:04 lucy kernel: iwn_notif_intr: scanning channel 157 status 1 Oct 23 15:49:04 lucy kernel: iwn_notif_intr: scanning channel 161 status 1 Oct 23 15:49:04 lucy kernel: iwn_notif_intr: scanning channel 100 status 1 Oct 23 15:49:04 lucy kernel: iwn_notif_intr: scanning channel 104 status 1 Oct 23 15:49:04 lucy kernel: iwn_notif_intr: scanning channel 108 status 1 Oct 23 15:49:04 lucy kernel: iwn_notif_intr: scanning channel 112 status 1 Oct 23 15:49:04 lucy kernel: iwn_notif_intr: scanning channel 116 status 1 Oct 23 15:49:04 lucy kernel: iwn_notif_intr: scanning channel 120 status 1 Oct 23 15:49:04 lucy kernel: iwn_notif_intr: scanning channel 124 status 1 Oct 23 15:49:04 lucy kernel: wlan0: [f8:e4:fb:1a:49:79] amrr_node_init: non-11n node Oct 23 15:49:04 lucy kernel: wlan0: [f8:e4:fb:1a:49:79] AMRR: nrates=0, initial rate 0 Oct 23 15:49:04 lucy kernel: wlan0: [f8:e4:fb:1a:49:79] amrr_node_init: 11n node Oct 23 15:49:04 lucy kernel: wlan0: [f8:e4:fb:1a:49:79] AMRR: nrates=16, initial rate 128 Oct 23 15:49:04 lucy kernel: iwn_tx_data_raw: qid 3 idx 0 len 6 nsegs 1 Oct 23 15:49:04 lucy kernel: iwn4965_tx_done: qid 3 idx 0 retries 0 nkill 0 rate 420a duration 778 status 3201 Oct 23 15:49:04 lucy kernel: iwn_tx_data_raw: qid 3 idx 1 len 93 nsegs 1 Oct 23 15:49:04 lucy kernel: iwn4965_tx_done: qid 3 idx 1 retries 0 nkill 0 rate 420a duration 1474 status 3201 Oct 23 15:49:04 lucy kernel: wlan0: [f8:e4:fb:1a:49:79] amrr_node_init: 11n node Oct 23 15:49:04 lucy kernel: wlan0: [f8:e4:fb:1a:49:79] AMRR: nrates=16, initial rate 128 Oct 23 15:49:04 lucy kernel: wlan0: link state changed to UP Oct 23 15:49:04 lucy kernel: iwn_tx_data_raw: qid 3 idx 2 len 9 nsegs 1 Oct 23 15:49:04 lucy kernel: temperature 319K/46C Oct 23 15:49:04 lucy kernel: iwn4965_tx_done: qid 3 idx 2 retries 0 nkill 0 rate 420a duration 802 status 3201 Oct 23 15:49:04 lucy kernel: iwn_tx_data: qid 3 idx 3 len 129 nsegs 2 Oct 23 15:49:04 lucy kernel: iwn4965_tx_done: qid 3 idx 3 retries 0 nkill 0 rate 4103 duration 138 status 3201 Oct 23 15:49:04 lucy kernel: iwn_tx_data: qid 3 idx 4 len 107 nsegs 2 Oct 23 15:49:04 lucy kernel: iwn4965_tx_done: qid 3 idx 4 retries 0 nkill 0 rate 4103 duration 130 status 3201 Oct 23 15:49:06 lucy kernel: iwn_tx_data: qid 0 idx 0 len 52 nsegs 2 Oct 23 15:49:06 lucy kernel: iwn4965_tx_done: qid 0 idx 0 retries 0 nkill 0 rate 4103 duration 114 status 201 Oct 23 15:49:06 lucy kernel: iwn_tx_data_raw: qid 3 idx 5 len 9 nsegs 1 Oct 23 15:49:06 lucy kernel: iwn4965_tx_done: qid 3 idx 5 retries 0 nkill 0 rate 420a duration 802 status 3201 Oct 23 15:49:06 lucy kernel: iwn_tx_data: qid 0 idx 1 len 108 nsegs 1 Oct 23 15:49:06 lucy kernel: iwn4965_tx_done: qid 0 idx 1 retries 0 nkill 0 rate 4103 duration 130 status 201 Oct 23 15:49:06 lucy kernel: iwn_tx_data: qid 0 idx 2 len 108 nsegs 1 Oct 23 15:49:06 lucy kernel: iwn4965_tx_done: qid 0 idx 2 retries 0 nkill 0 rate 4103 duration 130 status 201 Oct 23 15:49:06 lucy kernel: iwn_tx_data: qid 0 idx 3 len 108 nsegs 1 Oct 23 15:49:06 lucy kernel: iwn4965_tx_done: qid 0 idx 3 retries 0 nkill 0 rate 4103 duration 130 status 201 Oct 23 15:49:06 lucy kernel: iwn_tx_data: qid 0 idx 4 len 108 nsegs 1 Oct 23 15:49:06 lucy kernel: iwn4965_tx_done: qid 0 idx 4 retries 0 nkill 0 rate 4103 duration 130 status 201 Oct 23 15:49:06 lucy kernel: iwn_tx_data: qid 0 idx 5 len 108 nsegs 1 Oct 23 15:49:06 lucy kernel: iwn4965_tx_done: qid 0 idx 5 retries 0 nkill 0 rate 4103 duration 130 status 201 Oct 23 15:49:07 lucy kernel: iwn_tx_data: qid 0 idx 6 len 108 nsegs 1 Oct 23 15:49:07 lucy kernel: iwn4965_tx_done: qid 0 idx 6 retries 0 nkill 0 rate 4103 duration 130 status 201 Oct 23 15:49:07 lucy kernel: wlan0: [f8:e4:fb:1a:49:79] AMRR: current rate 15, txcnt=11, retrycnt=0 Oct 23 15:49:07 lucy kernel: iwn_tx_data: qid 0 idx 7 len 108 nsegs 1 Oct 23 15:49:07 lucy kernel: iwn4965_tx_done: qid 0 idx 7 retries 0 nkill 0 rate 4103 duration 130 status 201 Oct 23 15:49:07 lucy kernel: iwn_tx_data: qid 0 idx 8 len 108 nsegs 1 Oct 23 15:49:07 lucy kernel: iwn4965_tx_done: qid 0 idx 8 retries 0 nkill 0 rate 4103 duration 130 status 201 Oct 23 15:49:07 lucy kernel: iwn_tx_data: qid 0 idx 9 len 108 nsegs 1 Oct 23 15:49:07 lucy kernel: iwn4965_tx_done: qid 0 idx 9 retries 0 nkill 0 rate 4103 duration 130 status 201 Oct 23 15:49:11 lucy kernel: iwn_tx_data: qid 0 idx 10 len 52 nsegs 1 Oct 23 15:49:11 lucy kernel: iwn4965_tx_done: qid 0 idx 10 retries 0 nkill 0 rate 4103 duration 114 status 201 Oct 23 15:49:23 lucy kernel: temperature 322K/49C >How-To-Repeat: not sure yet. I just left things idle for a while. * Intel 4965, -HEAD iwn/net80211 running on stable/9 * connecting to an 11n 2-stream network, speaking WPA/WPA2 I'm not yet sure what those particular flags and status mean; but the rate looks suspicious. It's likely I should add some transmit setup logic to see if I'm initialising things wrong. Also, I think I'm initialising the MRR stuff wrong. When I updated the rate control code to return 11n rates instead of legacy only (and having the driver 'fake' 11n rates in return) the MRR stuff still uses ridx; and ridx always does a legacy rate table lookup. So, look at how that's done in iwn_tx_data() (and iwn_tx_data_raw()) in case I've screwed it up somehow. >Fix: >Release-Note: >Audit-Trail: >Unformatted: