From owner-freebsd-net@freebsd.org Fri Aug 19 22:47:55 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 55110BBFE7A for ; Fri, 19 Aug 2016 22:47:55 +0000 (UTC) (envelope-from kob6558@gmail.com) Received: from mailman.ysv.freebsd.org (unknown [127.0.1.3]) by mx1.freebsd.org (Postfix) with ESMTP id 35F5D1254 for ; Fri, 19 Aug 2016 22:47:55 +0000 (UTC) (envelope-from kob6558@gmail.com) Received: by mailman.ysv.freebsd.org (Postfix) id 319FFBBFE79; Fri, 19 Aug 2016 22:47:55 +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 313A0BBFE78 for ; Fri, 19 Aug 2016 22:47:55 +0000 (UTC) (envelope-from kob6558@gmail.com) Received: from mail-io0-x231.google.com (mail-io0-x231.google.com [IPv6:2607:f8b0:4001:c06::231]) (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 F0B5B1253 for ; Fri, 19 Aug 2016 22:47:54 +0000 (UTC) (envelope-from kob6558@gmail.com) Received: by mail-io0-x231.google.com with SMTP id b62so61857770iod.3 for ; Fri, 19 Aug 2016 15:47:54 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20120113; h=mime-version:sender:from:date:message-id:subject:to; bh=jMJECWppVVOUVNtoaTK5b8f+wi9BxVmD/aJ7WyE1EFg=; b=hP55HBdI0RdkCEUMrGbJTwYOXVSfQ5eCcKU32cQyVzf8wCaWq1x+xBtwwXJPvdfjb9 5XjFMLJe34YzcRAl21kjcy0Bo92lUPzWyXvkL11ftX7VF4dAhwNeQYuh3f7ZWtgjXB2F wnxKE5RswLoyU7XsjPv579iZZuPmu6FQdsMsH4YTRA5mxiT0MnQPT8m3eYj3W7f4+gl2 8vTIgiPIk06sYeZzkdmvjdv/zjHReMvunNfor6xGI4rEG5UAgT2AO1a3Mz0U6qEzXMe5 6Tc6yBE20B/gHHNTxi0ZIOHYhPpE3BG0srulfAVxanwvXmeQcLtElqN4q0NSSAJ/KRFD pUBQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20130820; h=x-gm-message-state:mime-version:sender:from:date:message-id:subject :to; bh=jMJECWppVVOUVNtoaTK5b8f+wi9BxVmD/aJ7WyE1EFg=; b=gDZnBAJaTOf2nK/13caltsW9T7frXDd4CV/hMRRY2D2vLPHptcrtOzKt/owxlmMo5G bHZDD+Tdxylegm7Tavt47V3zrVkuXwFnDbErF5L22/4gQBpwrY/fqeNkE7YjW5i6hteF rTX+dZ3OdIxf2LBc+T9X8QtUCQ1AnqQVkWPLlS0aCC4gvAuZf9n1g0u8OqdndDERINrK Vea9ocnl6vGqD4/og/eqK0sXKQ8M5Ub9Gt1gBZ98tQuse7MCBLvwaRoRw8MZ/jg11ts/ BJn7aLCRgrF62m/OHw9gdkykwxOfqjYUC62e+03Yns5i2+sUT9ZwAPgX4PV6AYSiXP5q 0/xA== X-Gm-Message-State: AEkooutiRtwWjosQUIAjiXzl2JNBVgDjcZyjKQjNQpiPAG5vX3U1f/FZOiELjA3r5e7jxw58QrLnfNuDXlteTw== X-Received: by 10.107.25.14 with SMTP id 14mr12031816ioz.168.1471646873971; Fri, 19 Aug 2016 15:47:53 -0700 (PDT) MIME-Version: 1.0 Sender: kob6558@gmail.com Received: by 10.79.119.144 with HTTP; Fri, 19 Aug 2016 15:47:53 -0700 (PDT) From: Kevin Oberman Date: Fri, 19 Aug 2016 15:47:53 -0700 X-Google-Sender-Auth: bkI-1yPTxRZVsLmuU4kD6n7M0bk Message-ID: Subject: iwn(4) association issues in 11-Stable (and maybe RC) To: FreeBSD Net 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: Fri, 19 Aug 2016 22:47:55 -0000 Lately I have had serious issues with my system successfully associating. These were not present with 10.3. > uname -a FreeBSD rogue 11.0-BETA4 FreeBSD 11.0-BETA4 #1 r303806: Sat Aug 6 18:50:50 PDT 2016 root@rogue:/usr/obj/usr/src/sys/GENERIC.4BSD amd64 iwn0@pci0:3:0:0: class=0x028000 card=0x13118086 chip=0x00858086 rev=0x34 hdr=0x00 cap 01[c8] = powerspec 3 supports D0 D3 current D0 cap 05[d0] = MSI supports 1 message, 64 bit enabled with 1 message cap 10[e0] = PCI-Express 1 endpoint max data 128(128) FLR RO NS link x1(x1) speed 2.5(2.5) ASPM L1(L0s/L1) ecap 0001[100] = AER 1 0 fatal 0 non-fatal 0 corrected ecap 0003[140] = Serial 1 a088b4ffffc6ad28 Once associated, it works fine, but a dropped association is often not re-established and the network fails to come up at boot time. Kernel is GENERIC except the 4BSD scheduler. I've been using a mobile hotspot this week during travels and it has become a real pain. With lot of patience and many "netif restart wlan0" operations, it will come up, but it can be painful. Here is what I see in messages: Aug 19 00:13:52 rogue kernel: wlan0: Ethernet address: a0:88:b4:c6:ad:28 Aug 19 00:13:52 rogue kernel: iwn0: iwn_read_firmware: ucode rev=0x12a80601 Aug 19 00:13:52 rogue kernel: wlan0: link state changed to UP Aug 19 00:13:52 rogue kernel: wlan0: link state changed to DOWN Aug 19 00:13:52 rogue kernel: iwn0: scan timeout Aug 19 00:13:52 rogue kernel: iwn0: iwn_read_firmware: ucode rev=0x12a80601 Aug 19 00:13:52 rogue kernel: wlan0: link state changed to UP Aug 19 00:13:52 rogue kernel: wlan0: link state changed to DOWN Aug 19 00:13:52 rogue kernel: iwn0: scan timeout Aug 19 00:13:52 rogue kernel: iwn0: iwn_read_firmware: ucode rev=0x12a80601 Aug 19 00:13:52 rogue kernel: wlan0: link state changed to UP Aug 19 00:13:52 rogue kernel: wlan0: link state changed to DOWN Aug 19 00:13:52 rogue kernel: iwn0: scan timeout Aug 19 00:13:52 rogue kernel: iwn0: iwn_read_firmware: ucode rev=0x12a80601 Aug 19 00:13:52 rogue kernel: wlan0: link state changed to UP Aug 19 00:13:52 rogue kernel: wlan0: link state changed to DOWN Aug 19 00:13:52 rogue kernel: iwn0: scan timeout Aug 19 00:13:52 rogue kernel: iwn0: iwn_read_firmware: ucode rev=0x12a80601 Aug 19 00:13:52 rogue kernel: wlan0: link state changed to UP Aug 19 00:13:52 rogue kernel: wlan0: link state changed to DOWN Aug 19 00:13:52 rogue kernel: iwn0: scan timeout Aug 19 00:13:52 rogue kernel: iwn0: iwn_read_firmware: ucode rev=0x12a80601 Aug 19 00:13:52 rogue kernel: wlan0: link state changed to UP Aug 19 00:13:52 rogue kernel: wlan0: link state changed to DOWN Aug 19 00:13:52 rogue kernel: iwn0: scan timeout Aug 19 00:13:52 rogue kernel: iwn0: iwn_read_firmware: ucode rev=0x12a80601 Aug 19 00:13:52 rogue kernel: wlan0: link state changed to UP Aug 19 00:13:52 rogue kernel: wlan0: link state changed to DOWN Aug 19 00:13:52 rogue kernel: iwn0: scan timeout Aug 19 00:13:52 rogue kernel: iwn0: iwn_read_firmware: ucode rev=0x12a80601 Aug 19 00:13:52 rogue kernel: wlan0: link state changed to UP Aug 19 00:13:52 rogue kernel: ipfw2 (+ipv6) initialized, divert loadable, nat loadable, default to deny, logging disabled Aug 19 00:13:52 rogue kernel: wlan0: link state changed to DOWN Aug 19 00:13:52 rogue kernel: iwn0: scan timeout Aug 19 00:13:52 rogue kernel: iwn0: iwn_read_firmware: ucode rev=0x12a80601 Aug 19 00:14:17 rogue dhclient[362]: send_packet: Network is down Aug 19 00:14:37 rogue dhclient[362]: send_packet: Network is down Aug 19 00:14:39 rogue wpa_supplicant[350]: wlan0: CTRL-EVENT-TERMINATING Aug 19 00:14:39 rogue dhclient[362]: connection closed Aug 19 00:14:39 rogue dhclient[362]: exiting. Aug 19 00:14:39 rogue rtsold[873]: interface wlan0 removed Aug 19 00:14:39 rogue kernel: wlan0: Ethernet address: a0:88:b4:c6:ad:28 Aug 19 00:14:39 rogue wpa_supplicant[1621]: Successfully initialized wpa_supplicant Aug 19 00:14:39 rogue wpa_supplicant[1633]: Successfully initialized wpa_supplicant Aug 19 00:14:39 rogue root: /etc/rc.d/wpa_supplicant: WARNING: failed to start wpa_supplicant Aug 19 00:14:39 rogue kernel: iwn0: iwn_read_firmware: ucode rev=0x12a80601 Aug 19 00:14:39 rogue wpa_supplicant[1634]: ioctl[SIOCS80211, op=103, val=0, arg_len=128]: Operation now in progress Aug 19 00:14:39 rogue wpa_supplicant[1634]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-1 retry=1 Aug 19 00:14:40 rogue wpa_supplicant[1634]: ioctl[SIOCS80211, op=103, val=0, arg_len=128]: Operation now in progress Aug 19 00:14:40 rogue wpa_supplicant[1634]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-1 retry=1 Aug 19 00:14:41 rogue wpa_supplicant[1634]: ioctl[SIOCS80211, op=103, val=0, arg_len=128]: Operation now in progress Aug 19 00:14:41 rogue wpa_supplicant[1634]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-1 retry=1 Aug 19 00:14:42 rogue wpa_supplicant[1634]: ioctl[SIOCS80211, op=103, val=0, arg_len=128]: Operation now in progress Aug 19 00:14:42 rogue wpa_supplicant[1634]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-1 retry=1 Aug 19 00:14:43 rogue wpa_supplicant[1634]: ioctl[SIOCS80211, op=103, val=0, arg_len=128]: Operation now in progress Aug 19 00:14:43 rogue wpa_supplicant[1634]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-1 retry=1 Aug 19 00:14:44 rogue wpa_supplicant[1634]: ioctl[SIOCS80211, op=103, val=0, arg_len=128]: Operation now in progress Aug 19 00:14:44 rogue wpa_supplicant[1634]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-1 retry=1 Aug 19 00:14:45 rogue wpa_supplicant[1634]: ioctl[SIOCS80211, op=103, val=0, arg_len=128]: Operation now in progress Aug 19 00:14:45 rogue wpa_supplicant[1634]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-1 retry=1 Aug 19 00:14:46 rogue wpa_supplicant[1634]: ioctl[SIOCS80211, op=103, val=0, arg_len=128]: Operation now in progress Aug 19 00:14:46 rogue wpa_supplicant[1634]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-1 retry=1 Aug 19 00:14:47 rogue wpa_supplicant[1634]: ioctl[SIOCS80211, op=103, val=0, arg_len=128]: Operation now in progress Aug 19 00:14:47 rogue wpa_supplicant[1634]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-1 retry=1 Aug 19 00:14:48 rogue wpa_supplicant[1634]: ioctl[SIOCS80211, op=103, val=0, arg_len=128]: Operation now in progress Aug 19 00:14:48 rogue wpa_supplicant[1634]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-1 retry=1 Aug 19 00:14:49 rogue wpa_supplicant[1634]: ioctl[SIOCS80211, op=103, val=0, arg_len=128]: Operation now in progress Aug 19 00:14:49 rogue wpa_supplicant[1634]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-1 retry=1 Aug 19 00:14:50 rogue wpa_supplicant[1634]: ioctl[SIOCS80211, op=103, val=0, arg_len=128]: Operation now in progress Aug 19 00:14:50 rogue wpa_supplicant[1634]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-1 retry=1 Aug 19 00:14:50 rogue root: /etc/rc.d/dhclient: WARNING: failed to start dhclient Aug 19 00:14:51 rogue wpa_supplicant[1634]: ioctl[SIOCS80211, op=103, val=0, arg_len=128]: Operation now in progress Aug 19 00:14:51 rogue wpa_supplicant[1634]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-1 retry=1 Aug 19 00:14:52 rogue wpa_supplicant[1634]: ioctl[SIOCS80211, op=103, val=0, arg_len=128]: Operation now in progress Aug 19 00:14:52 rogue wpa_supplicant[1634]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-1 retry=1 Aug 19 00:14:53 rogue wpa_supplicant[1634]: ioctl[SIOCS80211, op=103, val=0, arg_len=128]: Operation now in progress Aug 19 00:14:53 rogue wpa_supplicant[1634]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-1 retry=1 Is anyone else seeing this? Kevin Oberman, Part time kid herder and retired Network Engineer E-mail: rkoberman@gmail.com PGP Fingerprint: D03FB98AFA78E3B78C1694B318AB39EF1B055683