From owner-freebsd-net@freebsd.org Wed Aug 24 18:55:16 2016 Return-Path: Delivered-To: freebsd-net@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id 00DE9BC56B9 for ; Wed, 24 Aug 2016 18:55:16 +0000 (UTC) (envelope-from kob6558@gmail.com) Received: from mailman.ysv.freebsd.org (mailman.ysv.freebsd.org [IPv6:2001:1900:2254:206a::50:5]) by mx1.freebsd.org (Postfix) with ESMTP id CEEFF1ACA for ; Wed, 24 Aug 2016 18:55:15 +0000 (UTC) (envelope-from kob6558@gmail.com) Received: by mailman.ysv.freebsd.org (Postfix) id CA2D9BC56B8; Wed, 24 Aug 2016 18:55:15 +0000 (UTC) Delivered-To: net@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id C9C26BC56B7 for ; Wed, 24 Aug 2016 18:55:15 +0000 (UTC) (envelope-from kob6558@gmail.com) Received: from mail-it0-x22e.google.com (mail-it0-x22e.google.com [IPv6:2607:f8b0:4001:c0b::22e]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (Client CN "smtp.gmail.com", Issuer "Google Internet Authority G2" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id 8E55C1ABC; Wed, 24 Aug 2016 18:55:15 +0000 (UTC) (envelope-from kob6558@gmail.com) Received: by mail-it0-x22e.google.com with SMTP id f6so27957529ith.0; Wed, 24 Aug 2016 11:55:15 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20120113; h=mime-version:in-reply-to:references:from:date:message-id:subject:to :cc; bh=8vo4aLDnroOMu8t8b8OeJx0Wkzf4o3pkqdDr4QOQHAo=; b=XZF/Bg5HV0/ur3n1V2eWLWpipHSvSLdSWISSlt3mhPlx4QUA+beE/aYYssnvS8bD7G GjWmSOVsubnP4PyzR3Fg6Ohd0LMPslXLFfL7/AySFFcfb/Kp86/IRN0JjDUxk6tGN+xt N5/UAIzYyoh/GQNvcKbzcYP2x4Xz0MDfLUFSpqMHtHKNY6yE/RMGq4IZ8mA64CpCh9W0 erya8t5Hc3qtwaUr+r5eDzWSVjYASPsBu/BZ1/T+8faxLJQ68+e4WLjrZjweYs6/KOiQ G9DCbAEKAeX1Fbus81OooS+lenoiyCIeuLkffXOmAl8JldPgZNon78hN3tQV+JrmJKk8 U1+w== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20130820; h=x-gm-message-state:mime-version:in-reply-to:references:from:date :message-id:subject:to:cc; bh=8vo4aLDnroOMu8t8b8OeJx0Wkzf4o3pkqdDr4QOQHAo=; b=XLh6nM07Mmfk//osKuzsjzo28qIk352C8ovNgYJ5XLR0V81QRotYK30u9gZRvIUBta B63Ib3n6rnOF4zQ6ewLUhtAQJKlQg834VCMHsbG7y2IxZs6ADBP2NTkoclz55nhxuRil wlUxd4YyRFupIMjBFpSoV48zLAZv9QimgxCDBrxtMXJGD4NKeG26TFB2RS4nLgc0Quyr u9UJqJZtB69JmeSVkgVKfx0HjtrB9SH9Ymwzsv+bY0oeHfkAD1k8DL7806SAsEW9kaMc nsfZzOUqHEybdNHHrR+hKGgXxC3GqWWYAqlBgxWdKzhj5LMmiiBVWdY/TE0LMvi12jL2 jP5w== X-Gm-Message-State: AEkoouvvv5P/JYSTaPRrx43SL5Rds23rGITZs+FDdjjJmWkf5jxC3B61MNJiI+DsrxNPgtPX/2WiQcW+08NRZQ== X-Received: by 10.36.219.65 with SMTP id c62mr517157itg.44.1472064914788; Wed, 24 Aug 2016 11:55:14 -0700 (PDT) MIME-Version: 1.0 Received: by 10.79.109.198 with HTTP; Wed, 24 Aug 2016 11:55:13 -0700 (PDT) In-Reply-To: References: From: Kevin Oberman Date: Wed, 24 Aug 2016 11:55:13 -0700 Message-ID: Subject: Re: iwn(4) association issues in 11-Stable (and maybe RC) To: Adrian Chadd , FreeBSD Net Cc: =?UTF-8?Q?Vin=C3=ADcius_Zavam?= , Andriy Voskoboinyk Content-Type: text/plain; charset=UTF-8 X-Content-Filtered-By: Mailman/MimeDel 2.1.22 X-BeenThere: freebsd-net@freebsd.org X-Mailman-Version: 2.1.22 Precedence: list List-Id: Networking and TCP/IP with FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Wed, 24 Aug 2016 18:55:16 -0000 On Tue, Aug 23, 2016 at 10:40 PM, Kevin Oberman < kob6558@gmail.com> wrote: > On Tue, Aug 23, 2016 at 11:48 AM, Adrian Chadd < > adrian.chadd@gmail.com> wrote: > >> Hi, >> >> Compile in IWN_DEBUG and IEEE80211_DEBUG and then do: >> >> wlandebug +assoc +auth +state +rate >> sysctl debug.iwn.0.debug=0x1 >> >> that's TX debugging, and it hopefully will show it trying to do >> association and failing. My guess is that something changed when doing >> the 11n bits for -11 and it's failing to send out the 802.1x frame >> exchange. >> >> It may be something as simple as "adrian needs to fix the rate control >> again". >> >> >> >> -adrian >> > Not working right. I do see 802.11 messages but nothing from iwn. Rebuilt with: options IEEE80211_DEBUG options IWN_DEBUG > sysctl debug.iwn.0.debug=0x1 sysctl: unknown oid 'debug.iwn.0.debug' Exit 1 > sysctl -a | grep iwn device iwn net.wlan.0.%parent: iwn0 net.wlan.devices: iwn0 dev.iwn.0.debug: 0 dev.iwn.0.%parent: pci1 dev.iwn.0.%pnpinfo: vendor=0x8086 device=0x0085 subvendor=0x8086 subdevice=0x1311 class=0x028000 dev.iwn.0.%location: slot=0 function=0 dbsf=pci0:3:0:0 dev.iwn.0.%driver: iwn dev.iwn.0.%desc: Intel Centrino Advanced-N 6205 dev.iwn.%parent: > Here is what I did log. (In this case it did re-associate fairly quickly, unlike when I booted up and it took repeated tries to get an association.) Aug 24 09:54:57 rogue dhclient: New IP Address (wlan0): 192.168.1.5 Aug 24 09:54:57 rogue dhclient: New Subnet Mask (wlan0): 255.255.255.0 Aug 24 09:54:57 rogue dhclient: New Broadcast Address (wlan0): 192.168.1.255 Aug 24 09:54:57 rogue dhclient: New Routers (wlan0): 192.168.1.1 Aug 24 09:54:59 rogue dhclient: New Routers (wlan0): 192.168.1.1 Aug 24 09:56:28 rogue kernel: wlan0: [00:18:e7:dc:05:19] AMRR: current rate 15, txcnt=12, retrycnt=0 Aug 24 09:57:38 rogue kernel: wlan0: [00:18:e7:dc:05:19] AMRR: current rate 15, txcnt=11, retrycnt=0 Aug 24 09:58:43 rogue kernel: wlan0: [00:18:e7:dc:05:19] AMRR: current rate 15, txcnt=12, retrycnt=0 Aug 24 09:59:17 rogue wpa_supplicant[364]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:18:e7:dc:05:19 reason=3 locally_generated=1 Aug 24 09:59:17 rogue kernel: wlan0: [00:18:e7:dc:05:19] station deauth via MLME (reason: 3 (sending STA is leaving/has left IBSS or ESS)) Aug 24 09:59:17 rogue kernel: wlan0: ieee80211_new_state_locked: RUN -> INIT (nrunning 0 nscanning 0) Aug 24 09:59:17 rogue kernel: wlan0: ieee80211_newstate_cb: RUN -> INIT arg 3 Aug 24 09:59:17 rogue kernel: wlan0: sta_newstate: RUN -> INIT (3) Aug 24 09:59:17 rogue kernel: wlan0: [00:18:e7:dc:05:19] send station disassociate (reason: 8 (sending STA is leaving/has left BSS)) Aug 24 09:59:17 rogue kernel: wlan0: [a0:88:b4:c6:ad:28] amrr_node_init: non-11n node Aug 24 09:59:17 rogue kernel: wlan0: [a0:88:b4:c6:ad:28] AMRR: nrates=0, initial rate 0 Aug 24 09:59:17 rogue kernel: wlan0: link state changed to DOWN Aug 24 09:59:17 rogue kernel: wlan0: stop running, 1 vaps running Aug 24 09:59:17 rogue kernel: wlan0: ieee80211_new_state_locked: INIT -> INIT (nrunning 0 nscanning 0) Aug 24 09:59:17 rogue kernel: wlan0: down parent iwn0 Aug 24 09:59:17 rogue kernel: wlan0: ieee80211_newstate_cb: INIT -> INIT arg -1 Aug 24 09:59:17 rogue kernel: wlan0: sta_newstate: INIT -> INIT (-1) Aug 24 09:59:17 rogue wpa_supplicant[364]: wlan0: CTRL-EVENT-TERMINATING Aug 24 09:59:17 rogue dhclient[376]: connection closed Aug 24 09:59:17 rogue dhclient[376]: exiting. Aug 24 09:59:17 rogue kernel: wlan0: ieee80211_vap_detach: STA parent iwn0 Aug 24 09:59:17 rogue kernel: wlan0: stop running, 0 vaps running Aug 24 09:59:17 rogue kernel: wlan0: ieee80211_new_state_locked: INIT -> INIT (nrunning 0 nscanning 0) Aug 24 09:59:17 rogue kernel: wlan0: ieee80211_newstate_cb: INIT -> INIT arg -1 Aug 24 09:59:17 rogue kernel: wlan0: sta_newstate: INIT -> INIT (-1) Aug 24 09:59:17 rogue rtsold[817]: interface wlan0 removed Aug 24 09:59:17 rogue kernel: wlan0: Ethernet address: a0:88:b4:c6:ad:28 Aug 24 09:59:17 rogue wpa_supplicant[1638]: Successfully initialized wpa_supplicant Aug 24 09:59:18 rogue wpa_supplicant[1655]: Successfully initialized wpa_supplicant Aug 24 09:59:18 rogue root: /etc/rc.d/wpa_supplicant: WARNING: failed to start wpa_supplicant Aug 24 09:59:18 rogue wpa_supplicant[1656]: ioctl[SIOCS80211, op=103, val=0, arg_len=128]: Operation now in progress Aug 24 09:59:18 rogue kernel: iwn0: iwn_read_firmware: ucode rev=0x12a80601 Aug 24 09:59:18 rogue wpa_supplicant[1656]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-1 retry=1 Aug 24 09:59:19 rogue wpa_supplicant[1656]: ioctl[SIOCS80211, op=103, val=0, arg_len=128]: Operation now in progress Aug 24 09:59:19 rogue wpa_supplicant[1656]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-1 retry=1 Aug 24 09:59:19 rogue wpa_supplicant[1656]: wlan0: Trying to associate with 00:18:e7:dc:05:19 (SSID='babcom' freq=2462 MHz) Aug 24 09:59:29 rogue wpa_supplicant[1656]: wlan0: Authentication with 00:18:e7:dc:05:19 timed out. Aug 24 09:59:29 rogue wpa_supplicant[1656]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:18:e7:dc:05:19 reason=3 locally_generated=1 Aug 24 09:59:29 rogue oberman: /etc/rc.d/dhclient: WARNING: failed to start dhclient Aug 24 09:59:30 rogue wpa_supplicant[1656]: wlan0: Trying to associate with 00:18:e7:dc:05:19 (SSID='babcom' freq=2462 MHz) Aug 24 09:59:30 rogue wpa_supplicant[1656]: wlan0: Associated with 00:18:e7:dc:05:19 Aug 24 09:59:30 rogue kernel: wlan0: link state changed to UP Aug 24 09:59:30 rogue wpa_supplicant[1656]: wlan0: WPA: Key negotiation completed with 00:18:e7:dc:05:19 [PTK=CCMP GTK=TKIP] Aug 24 09:59:30 rogue wpa_supplicant[1656]: wlan0: CTRL-EVENT-CONNECTED - Connection to 00:18:e7:dc:05:19 completed [id=1 id_str=] Aug 24 09:59:31 rogue dhclient: New IP Address (wlan0): 192.168.1.5 Aug 24 09:59:31 rogue dhclient: New Subnet Mask (wlan0): 255.255.255.0 Aug 24 09:59:31 rogue dhclient: New Broadcast Address (wlan0): 192.168.1.255 Aug 24 09:59:31 rogue dhclient: New Routers (wlan0): 192.168.1.1 Any idea what is going on?