Frequent connection problems (and hangs) with D-Link DIR-860L B1 (mt76) and iwlwifi client

Borromini · December 3, 2016, 4:45pm

I recently switched from my beloved WNDR3700 to (what I believed to be a good upgrade ) a D-Link DIR-860L rev B1. Client is a Skylake Dell XPS 13, on Debian Stretch, with an Intel 8260 802.11AC card.

Symptoms:

I get frequent hangs where the wireless connection will stop altogether despite it seemingly being still connected (NetworkManager shows a signal still).
In other cases, it will take ages to connect to the AP, sometimes requiring multiple minutes, to the point of NetworkManager giving up after a while. Disabling wireless and re-enabling it and/or restarting NetworkManager helps sometimes.

This happens frequently (as in: sometimes every five minutes); at almost every boot as well. I have set up my old WNDR3700 as an AP again as a fall-back. When the connection with the D-Link hangs, I switch to the Netgear and it almost immediately connects (like one would expect). The connection with the ath9k AP is a lot more stable. Both are on recent LEDE builds - the D-Link on r2340+2 and the Netgear on r2116+2 (the +2 are a patch for extra APU2 stuff + 4.4 kernel bump).

What I tried:

I have tested 4.7, 4.8 and the 4.9 RC5 kernel, problem persists with all those kernels.
Googling suggests the Intel firmware may be part of the problem, but when I revert to older firmwares (by deleting .22 e.g. in /lib/firmware/), that doesn't change anything. The 4.9 iwlwifi driver is already looking for .26 microcode, but Intel is not distributing anything beyond .22 (at least, not in public). So I'm not sure where to start.
Disabling 802.11n with iwlwifi.11n_disable=8 or iwlwifi.11n_disable=0. Neither change anything.

I see a lot of 'deauthenticating by local choice' which must be some software logic, because it happens without me clicking anything. Another thing that pops up quite frequently is the 'No association an the time event is over already', which seems in line with firmware problems people have been seing with older 7260AC firmwares.

Dmesg log:

[    7.366833] iwlwifi 0000:3a:00.0: SecBoot CPU1 Status: 0x3090003, CPU2 Status: 0x0
[    7.366974] iwlwifi 0000:3a:00.0: Failed to start RT ucode: -110
[    7.420034] iwlwifi 0000:3a:00.0: L1 Enabled - LTR Disabled
[    7.420307] iwlwifi 0000:3a:00.0: L1 Enabled - LTR Disabled
[    7.559034] iwlwifi 0000:3a:00.0: L1 Enabled - LTR Disabled
[    7.559325] iwlwifi 0000:3a:00.0: L1 Enabled - LTR Disabled
[    7.664010] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[    7.731674] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[   11.296964] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[   11.411697] wlan0: authenticate with e4:6f:13:xx:xx:xx
[   11.420813] wlan0: send auth to e4:6f:13:xx:xx:xx (try 1/3)
[   11.426689] wlan0: authenticated
[   11.430667] wlan0: associate with e4:6f:13:xx:xx:xx (try 1/3)
[   11.432373] wlan0: RX AssocResp from e4:6f:13:xx:xx:xx (capab=0x11 status=0 aid=2)
[   11.435002] wlan0: associated
[   11.435127] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[   57.049330] wlan0: deauthenticating from e4:6f:13:xx:xx:xx by local choice (Reason: 3=DEAUTH_LEAVING)
[   57.065977] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[   57.093910] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[   58.247336] wlan0: authenticate with e4:6f:13:xx:xx:xx
[   58.255322] wlan0: send auth to e4:6f:13:xx:xx:xx (try 1/3)
[   58.257166] wlan0: authenticated
[   58.869641] iwlwifi 0000:3a:00.0: No association and the time event is over already...
[   58.869691] wlan0: Connection to AP e4:6f:13:xx:xx:xx lost
[   63.260745] wlan0: aborting authentication with e4:6f:13:xx:xx:xx by local choice (Reason: 3=DEAUTH_LEAVING)
[   64.511871] wlan0: authenticate with e4:6f:13:xx:xx:xx
[   64.519380] wlan0: send auth to e4:6f:13:xx:xx:xx (try 1/3)
[   64.520936] wlan0: authenticated
[   65.133787] iwlwifi 0000:3a:00.0: No association and the time event is over already...
[   65.133921] wlan0: Connection to AP e4:6f:13:xx:xx:xx lost
[   69.521536] wlan0: aborting authentication with e4:6f:13:xx:xx:xx by local choice (Reason: 3=DEAUTH_LEAVING)
[   71.138063] wlan0: authenticate with e4:6f:13:xx:xx:xx
[   71.145179] wlan0: send auth to e4:6f:13:xx:xx:xx (try 1/3)
[   71.146292] wlan0: authenticated
[   71.759603] iwlwifi 0000:3a:00.0: No association and the time event is over already...
[   71.759740] wlan0: Connection to AP e4:6f:13:xx:xx:xx lost
[   76.150547] wlan0: aborting authentication with e4:6f:13:xx:xx:xx by local choice (Reason: 3=DEAUTH_LEAVING)
[   78.377081] wlan0: authenticate with e4:6f:13:xx:xx:xx
[   78.384201] wlan0: send auth to e4:6f:13:xx:xx:xx (try 1/3)
[   78.385360] wlan0: authenticated
[   78.998535] iwlwifi 0000:3a:00.0: No association and the time event is over already...
[   78.998668] wlan0: Connection to AP e4:6f:13:xx:xx:xx lost
[   82.010498] wlan0: aborting authentication with e4:6f:13:xx:xx:xx by local choice (Reason: 3=DEAUTH_LEAVING)
[   82.016868] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[   82.029046] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[   82.083655] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[   82.153733] wlan0: authenticate with e4:6f:13:xx:xx:xx
[   82.162770] wlan0: send auth to e4:6f:13:xx:xx:xx (try 1/3)
[   82.166009] wlan0: authenticated
[   82.166292] wlan0: associate with e4:6f:13:xx:xx:xx (try 1/3)
[   82.168146] wlan0: RX AssocResp from e4:6f:13:xx:xx:xx (capab=0x11 status=0 aid=2)
[   82.170568] wlan0: associated
[   82.170611] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[  128.035289] wlan0: deauthenticating from e4:6f:13:xx:xx:xx by local choice (Reason: 3=DEAUTH_LEAVING)
[  128.057756] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[  128.090221] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[  130.827466] wlan0: authenticate with e4:6f:13:xx:xx:xx
[  130.834536] wlan0: send auth to e4:6f:13:xx:xx:xx (try 1/3)
[  130.836258] wlan0: authenticated
[  130.838147] wlan0: associate with e4:6f:13:xx:xx:xx (try 1/3)
[  130.839458] wlan0: RX AssocResp from e4:6f:13:xx:xx:xx (capab=0x11 status=0 aid=2)
[  130.840877] wlan0: associated
[  130.840910] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[  176.053201] wlan0: deauthenticating from e4:6f:13:xx:xx:xx by local choice (Reason: 3=DEAUTH_LEAVING)
[  176.076266] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready

I just had another hang, after which I disabled the wifi and enabled it again. Dmesg output:

[    5.477049] iwlwifi 0000:3a:00.0: SecBoot CPU1 Status: 0x3090003, CPU2 Status: 0x0
[    5.477081] iwlwifi 0000:3a:00.0: Failed to start RT ucode: -110
[    5.500628] iwlwifi 0000:3a:00.0: L1 Enabled - LTR Disabled
[    5.500917] iwlwifi 0000:3a:00.0: L1 Enabled - LTR Disabled
[    5.638189] iwlwifi 0000:3a:00.0: L1 Enabled - LTR Disabled
[    5.638462] iwlwifi 0000:3a:00.0: L1 Enabled - LTR Disabled
[    5.742053] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[    5.782094] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[    7.874150] hrtimer: interrupt took 541154 ns
[    9.253916] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[    9.305612] wlan0: authenticate with xx:6f:13:xx:bf:xx
[    9.312188] wlan0: send auth to xx:6f:13:xx:bf:xx (try 1/3)
[    9.317788] wlan0: authenticated
[    9.320901] wlan0: associate with xx:6f:13:xx:bf:xx (try 1/3)
[    9.322147] wlan0: RX AssocResp from xx:6f:13:xx:bf:xx (capab=0x11 status=0 aid=2)
[    9.324000] wlan0: associated
[    9.324057] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[ 1099.338183] wlan0: deauthenticated from e4:6f:13:2e:bf:2a (Reason: 2=PREV_AUTH_NOT_VALID)
[ 1101.211482] wlan0: authenticate with xx:6f:13:xx:bf:xx
[ 1101.218623] wlan0: send auth to xx:6f:13:xx:bf:xx (try 1/3)
[ 1101.220554] wlan0: authenticated
[ 1101.222249] wlan0: associate with xx:6f:13:xx:bf:xx (try 1/3)
[ 1101.223376] wlan0: RX AssocResp from xx:6f:13:xx:bf:xx (capab=0x11 status=0 aid=2)
[ 1101.225430] wlan0: associated
[ 1154.777405] wlan0: deauthenticating from xx:6f:13:xx:bf:xx by local choice (Reason: 3=DEAUTH_LEAVING)

This is an older log, from repeated attempts to authenticate:

$ sudo tail -f /var/log/messages
Nov  7 21:22:34 icarus kernel: [  114.732907] wlan0: RX AssocResp from aa:bb:cc:xx:xx:xx (capab=0x11 status=0 aid=2)
Nov  7 21:22:34 icarus kernel: [  114.734985] wlan0: associated
Nov  7 21:22:34 icarus kernel: [  114.735021] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Nov  7 21:22:34 icarus NetworkManager[1998]: <info>  [1478550154.7079] device (wlan0): supplicant interface state: authenticating -> associated
Nov  7 21:22:34 icarus NetworkManager[1998]: <info>  [1478550154.7940] device (wlan0): supplicant interface state: associated -> 4-way handshake
Nov  7 21:22:34 icarus NetworkManager[1998]: <info>  [1478550154.9130] device (wlan0): supplicant interface state: 4-way handshake -> completed
Nov  7 21:22:34 icarus NetworkManager[1998]: <info>  [1478550154.9131] device (wlan0): Activation: (wifi) Stage 2 of 5 (Device Configure) successful.  Connected to wireless network 'Zeus 802.11ac'.
Nov  7 21:22:34 icarus NetworkManager[1998]: <info>  [1478550154.9133] device (wlan0): state change: config -> ip-config (reason 'none') [50 70 0]
Nov  7 21:22:34 icarus NetworkManager[1998]: <info>  [1478550154.9166] dhcp4 (wlan0): activation: beginning transaction (timeout in 45 seconds)
Nov  7 21:22:34 icarus NetworkManager[1998]: <info>  [1478550154.9223] dhcp4 (wlan0): dhclient started with pid 2056
Nov  7 21:23:19 icarus NetworkManager[1998]: <warn>  [1478550199.9774] dhcp4 (wlan0): request timed out
Nov  7 21:23:19 icarus NetworkManager[1998]: <info>  [1478550199.9776] dhcp4 (wlan0): state changed unknown -> timeout
Nov  7 21:23:20 icarus NetworkManager[1998]: <info>  [1478550200.0107] dhcp4 (wlan0): canceled DHCP transaction, DHCP client pid 2056
Nov  7 21:23:20 icarus NetworkManager[1998]: <info>  [1478550200.0108] dhcp4 (wlan0): state changed timeout -> done
Nov  7 21:23:20 icarus NetworkManager[1998]: <info>  [1478550200.0118] device (wlan0): state change: ip-config -> failed (reason 'ip-config-unavailable') [70 120 5]
Nov  7 21:23:20 icarus NetworkManager[1998]: <info>  [1478550200.0125] manager: NetworkManager state is now DISCONNECTED
Nov  7 21:23:20 icarus NetworkManager[1998]: <warn>  [1478550200.0163] device (wlan0): Activation: failed for connection 'Zeus 802.11ac'
Nov  7 21:23:20 icarus NetworkManager[1998]: <info>  [1478550200.0195] device (wlan0): state change: failed -> disconnected (reason 'none') [120 30 0]
Nov  7 21:23:20 icarus kernel: [  160.058660] wlan0: deauthenticating from aa:bb:cc:xx:xx:xx by local choice (Reason: 3=DEAUTH_LEAVING)
Nov  7 21:23:20 icarus NetworkManager[1998]: <info>  [1478550200.0461] device (wlan0): set-hw-addr: set MAC address to DA:3A:18:xx:xx:xx (scanning)
Nov  7 21:23:20 icarus kernel: [  160.082756] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Nov  7 21:23:20 icarus NetworkManager[1998]: <warn>  [1478550200.0650] sup-iface[0x1b01140,wlan0]: connection disconnected (reason -3)
Nov  7 21:23:20 icarus NetworkManager[1998]: <info>  [1478550200.0651] device (wlan0): supplicant interface state: completed -> disconnected
Nov  7 21:23:20 icarus NetworkManager[1998]: <info>  [1478550200.0700] policy: auto-activating connection 'Zeus 802.11ac'
Nov  7 21:23:20 icarus NetworkManager[1998]: <info>  [1478550200.0722] device (wlan0): Activation: starting connection 'Zeus 802.11ac' (6a156978-f2e3-4bc1-abd2-d44a9018226f)
Nov  7 21:23:20 icarus NetworkManager[1998]: <info>  [1478550200.0724] device (wlan0): state change: disconnected -> prepare (reason 'none') [30 40 0]
Nov  7 21:23:20 icarus NetworkManager[1998]: <info>  [1478550200.0747] manager: NetworkManager state is now CONNECTING
Nov  7 21:23:20 icarus NetworkManager[1998]: <info>  [1478550200.0802] device (wlan0): set-hw-addr: set-cloned MAC address to A4:34:D9:xx:xx:xx (permanent)
Nov  7 21:23:20 icarus NetworkManager[1998]: <info>  [1478550200.0887] device (wlan0): state change: prepare -> config (reason 'none') [40 50 0]
Nov  7 21:23:20 icarus NetworkManager[1998]: <info>  [1478550200.0889] device (wlan0): Activation: (wifi) access point 'Zeus 802.11ac' has security, but secrets are required.
Nov  7 21:23:20 icarus NetworkManager[1998]: <info>  [1478550200.0889] device (wlan0): state change: config -> need-auth (reason 'none') [50 60 0]
Nov  7 21:23:20 icarus kernel: [  160.115782] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Nov  7 21:23:20 icarus NetworkManager[1998]: <info>  [1478550200.0926] device (wlan0): state change: need-auth -> prepare (reason 'none') [60 40 0]
Nov  7 21:23:20 icarus NetworkManager[1998]: <info>  [1478550200.0933] device (wlan0): state change: prepare -> config (reason 'none') [40 50 0]
Nov  7 21:23:20 icarus NetworkManager[1998]: <info>  [1478550200.0934] device (wlan0): Activation: (wifi) connection 'Zeus 802.11ac' has security, and secrets exist.  No new secrets needed.
Nov  7 21:23:20 icarus NetworkManager[1998]: <info>  [1478550200.0935] Config: added 'ssid' value 'Zeus 802.11ac'
Nov  7 21:23:20 icarus NetworkManager[1998]: <info>  [1478550200.0935] Config: added 'scan_ssid' value '1'
Nov  7 21:23:20 icarus NetworkManager[1998]: <info>  [1478550200.0935] Config: added 'key_mgmt' value 'WPA-PSK'
Nov  7 21:23:20 icarus NetworkManager[1998]: <info>  [1478550200.0935] Config: added 'auth_alg' value 'OPEN'
Nov  7 21:23:20 icarus NetworkManager[1998]: <info>  [1478550200.0935] Config: added 'psk' value '<omitted>'
Nov  7 21:23:20 icarus NetworkManager[1998]: <info>  [1478550200.0956] device (wlan0): supplicant interface state: disconnected -> inactive
Nov  7 21:23:20 icarus NetworkManager[1998]: <info>  [1478550200.1207] sup-iface[0x1b01140,wlan0]: config: set interface ap_scan to 1
Nov  7 21:23:21 icarus kernel: [  161.726435] wlan0: authenticate with aa:bb:cc:xx:xx:xx
Nov  7 21:23:21 icarus NetworkManager[1998]: <info>  [1478550201.7053] device (wlan0): supplicant interface state: inactive -> authenticating
Nov  7 21:23:21 icarus kernel: [  161.733868] wlan0: send auth to aa:bb:cc:xx:xx:xx (try 1/3)
Nov  7 21:23:21 icarus kernel: [  161.735640] wlan0: authenticated
Nov  7 21:23:22 icarus kernel: [  162.347627] wlan0: Connection to AP aa:bb:cc:xx:xx:xx lost
Nov  7 21:23:26 icarus kernel: [  166.739117] wlan0: aborting authentication with aa:bb:cc:xx:xx:xx by local choice (Reason: 3=DEAUTH_LEAVING)
Nov  7 21:23:26 icarus NetworkManager[1998]: <info>  [1478550206.7219] device (wlan0): supplicant interface state: authenticating -> disconnected
Nov  7 21:23:27 icarus NetworkManager[1998]: <info>  [1478550207.2230] device (wlan0): supplicant interface state: disconnected -> scanning
Nov  7 21:23:28 icarus kernel: [  169.018409] wlan0: authenticate with aa:bb:cc:xx:xx:xx
Nov  7 21:23:28 icarus NetworkManager[1998]: <info>  [1478550208.9967] device (wlan0): supplicant interface state: scanning -> authenticating
Nov  7 21:23:28 icarus kernel: [  169.025489] wlan0: send auth to aa:bb:cc:xx:xx:xx (try 1/3)
Nov  7 21:23:28 icarus kernel: [  169.027382] wlan0: authenticated
Nov  7 21:23:29 icarus kernel: [  169.639669] wlan0: Connection to AP aa:bb:cc:xx:xx:xx lost
Nov  7 21:23:34 icarus kernel: [  174.028617] wlan0: aborting authentication with aa:bb:cc:xx:xx:xx by local choice (Reason: 3=DEAUTH_LEAVING)
Nov  7 21:23:34 icarus NetworkManager[1998]: <info>  [1478550214.0117] device (wlan0): supplicant interface state: authenticating -> disconnected
Nov  7 21:23:35 icarus NetworkManager[1998]: <info>  [1478550215.0132] device (wlan0): supplicant interface state: disconnected -> scanning
Nov  7 21:23:36 icarus kernel: [  176.808976] wlan0: authenticate with aa:bb:cc:xx:xx:xx
Nov  7 21:23:36 icarus kernel: [  176.816098] wlan0: send auth to aa:bb:cc:xx:xx:xx (try 1/3)
Nov  7 21:23:36 icarus kernel: [  176.817622] wlan0: authenticated
Nov  7 21:23:36 icarus NetworkManager[1998]: <info>  [1478550216.7984] device (wlan0): supplicant interface state: scanning -> authenticating
Nov  7 21:23:37 icarus kernel: [  177.430252] wlan0: Connection to AP aa:bb:cc:xx:xx:xx lost
Nov  7 21:23:41 icarus kernel: [  181.817096] wlan0: aborting authentication with aa:bb:cc:xx:xx:xx by local choice (Reason: 3=DEAUTH_LEAVING)
Nov  7 21:23:41 icarus NetworkManager[1998]: <info>  [1478550221.8002] device (wlan0): supplicant interface state: authenticating -> disconnected
Nov  7 21:23:44 icarus NetworkManager[1998]: <warn>  [1478550224.9766] device (wlan0): Activation: (wifi) association took too long, failing activation
Nov  7 21:23:44 icarus NetworkManager[1998]: <info>  [1478550224.9768] device (wlan0): state change: config -> failed (reason 'ssid-not-found') [50 120 53]
Nov  7 21:23:44 icarus NetworkManager[1998]: <info>  [1478550224.9776] manager: NetworkManager state is now DISCONNECTED
Nov  7 21:23:44 icarus NetworkManager[1998]: <warn>  [1478550224.9801] device (wlan0): Activation: failed for connection 'Zeus 802.11ac'
Nov  7 21:23:44 icarus NetworkManager[1998]: <info>  [1478550224.9816] device (wlan0): state change: failed -> disconnected (reason 'none') [120 30 0]
Nov  7 21:23:44 icarus kernel: [  185.011263] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Nov  7 21:23:44 icarus NetworkManager[1998]: <info>  [1478550224.9879] device (wlan0): set-hw-addr: set MAC address to 0E:C5:F2:xx:xx:xx (scanning)
Nov  7 21:23:44 icarus kernel: [  185.023922] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Nov  7 21:23:45 icarus NetworkManager[1998]: <info>  [1478550225.0100] device (wlan0): supplicant interface state: disconnected -> disabled
Nov  7 21:23:45 icarus NetworkManager[1998]: <info>  [1478550225.0173] policy: auto-activating connection 'Zeus 802.11ac'
Nov  7 21:23:45 icarus NetworkManager[1998]: <info>  [1478550225.0189] device (wlan0): Activation: starting connection 'Zeus 802.11ac' (6a156978-f2e3-4bc1-abd2-d44a9018226f)
Nov  7 21:23:45 icarus NetworkManager[1998]: <info>  [1478550225.0192] device (wlan0): state change: disconnected -> prepare (reason 'none') [30 40 0]
Nov  7 21:23:45 icarus NetworkManager[1998]: <info>  [1478550225.0193] manager: NetworkManager state is now CONNECTING
Nov  7 21:23:45 icarus NetworkManager[1998]: <info>  [1478550225.0262] device (wlan0): set-hw-addr: set-cloned MAC address to A4:34:D9:xx:xx:xx (permanent)
Nov  7 21:23:45 icarus kernel: [  185.061288] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Nov  7 21:23:45 icarus NetworkManager[1998]: <info>  [1478550225.0331] device (wlan0): supplicant interface state: disabled -> inactive
Nov  7 21:23:45 icarus NetworkManager[1998]: <info>  [1478550225.0334] device (wlan0): state change: prepare -> config (reason 'none') [40 50 0]
Nov  7 21:23:45 icarus NetworkManager[1998]: <info>  [1478550225.0340] device (wlan0): Activation: (wifi) access point 'Zeus 802.11ac' has security, but secrets are required.
Nov  7 21:23:45 icarus NetworkManager[1998]: <info>  [1478550225.0340] device (wlan0): state change: config -> need-auth (reason 'none') [50 60 0]
Nov  7 21:23:45 icarus NetworkManager[1998]: <info>  [1478550225.0383] device (wlan0): state change: need-auth -> prepare (reason 'none') [60 40 0]
Nov  7 21:23:45 icarus NetworkManager[1998]: <info>  [1478550225.0391] device (wlan0): state change: prepare -> config (reason 'none') [40 50 0]
Nov  7 21:23:45 icarus NetworkManager[1998]: <info>  [1478550225.0393] device (wlan0): Activation: (wifi) connection 'Zeus 802.11ac' has security, and secrets exist.  No new secrets needed.
Nov  7 21:23:45 icarus NetworkManager[1998]: <info>  [1478550225.0393] Config: added 'ssid' value 'Zeus 802.11ac'
Nov  7 21:23:45 icarus NetworkManager[1998]: <info>  [1478550225.0393] Config: added 'scan_ssid' value '1'
Nov  7 21:23:45 icarus NetworkManager[1998]: <info>  [1478550225.0393] Config: added 'key_mgmt' value 'WPA-PSK'
Nov  7 21:23:45 icarus NetworkManager[1998]: <info>  [1478550225.0393] Config: added 'auth_alg' value 'OPEN'
Nov  7 21:23:45 icarus NetworkManager[1998]: <info>  [1478550225.0393] Config: added 'psk' value '<omitted>'
Nov  7 21:23:45 icarus NetworkManager[1998]: <info>  [1478550225.0660] sup-iface[0x1b01140,wlan0]: config: set interface ap_scan to 1
Nov  7 21:23:46 icarus kernel: [  186.672180] wlan0: authenticate with aa:bb:cc:xx:xx:xx
Nov  7 21:23:46 icarus NetworkManager[1998]: <info>  [1478550226.6496] device (wlan0): supplicant interface state: inactive -> authenticating
Nov  7 21:23:46 icarus kernel: [  186.677729] wlan0: send auth to aa:bb:cc:xx:xx:xx (try 1/3)
Nov  7 21:23:46 icarus kernel: [  186.688283] wlan0: authenticated
Nov  7 21:23:47 icarus kernel: [  187.292235] wlan0: Connection to AP aa:bb:cc:xx:xx:xx lost
Nov  7 21:23:51 icarus kernel: [  191.678734] wlan0: aborting authentication with aa:bb:cc:xx:xx:xx by local choice (Reason: 3=DEAUTH_LEAVING)
Nov  7 21:23:51 icarus NetworkManager[1998]: <info>  [1478550231.6637] device (wlan0): supplicant interface state: authenticating -> disconnected
Nov  7 21:24:01 icarus NetworkManager[1998]: <info>  [1478550241.6650] device (wlan0): supplicant interface state: disconnected -> scanning
Nov  7 21:24:04 icarus kernel: [  204.592823] wlan0: authenticate with aa:bb:cc:xx:xx:xx
Nov  7 21:24:04 icarus kernel: [  204.599917] wlan0: send auth to aa:bb:cc:xx:xx:xx (try 1/3)
Nov  7 21:24:04 icarus NetworkManager[1998]: <info>  [1478550244.5721] device (wlan0): supplicant interface state: scanning -> authenticating
Nov  7 21:24:04 icarus kernel: [  204.601497] wlan0: authenticated
Nov  7 21:24:05 icarus kernel: [  205.214486] wlan0: Connection to AP aa:bb:cc:xx:xx:xx lost
Nov  7 21:24:09 icarus kernel: [  209.605606] wlan0: aborting authentication with aa:bb:cc:xx:xx:xx by local choice (Reason: 3=DEAUTH_LEAVING)
Nov  7 21:24:09 icarus NetworkManager[1998]: <info>  [1478550249.5891] device (wlan0): supplicant interface state: authenticating -> disconnected
Nov  7 21:24:09 icarus NetworkManager[1998]: <warn>  [1478550249.9764] device (wlan0): Activation: (wifi) association took too long, failing activation
Nov  7 21:24:09 icarus NetworkManager[1998]: <info>  [1478550249.9765] device (wlan0): state change: config -> failed (reason 'ssid-not-found') [50 120 53]
Nov  7 21:24:09 icarus NetworkManager[1998]: <info>  [1478550249.9772] manager: NetworkManager state is now DISCONNECTED
Nov  7 21:24:09 icarus NetworkManager[1998]: <warn>  [1478550249.9795] device (wlan0): Activation: failed for connection 'Zeus 802.11ac'
Nov  7 21:24:09 icarus NetworkManager[1998]: <info>  [1478550249.9823] device (wlan0): state change: failed -> disconnected (reason 'none') [120 30 0]
Nov  7 21:24:09 icarus NetworkManager[1998]: <info>  [1478550249.9861] device (wlan0): set-hw-addr: set MAC address to 96:14:BF:xx:xx:xx (scanning)
Nov  7 21:24:09 icarus kernel: [  210.012041] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Nov  7 21:24:09 icarus NetworkManager[1998]: <info>  [1478550249.9892] policy: auto-activating connection 'Zeus 802.11ac'
Nov  7 21:24:09 icarus kernel: [  210.017347] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Nov  7 21:24:09 icarus NetworkManager[1998]: <info>  [1478550249.9904] device (wlan0): Activation: starting connection 'Zeus 802.11ac' (6a156978-f2e3-4bc1-abd2-d44a9018226f)
Nov  7 21:24:09 icarus NetworkManager[1998]: <info>  [1478550249.9906] device (wlan0): state change: disconnected -> prepare (reason 'none') [30 40 0]
Nov  7 21:24:09 icarus NetworkManager[1998]: <info>  [1478550249.9907] manager: NetworkManager state is now CONNECTING
Nov  7 21:24:09 icarus NetworkManager[1998]: <info>  [1478550249.9966] device (wlan0): set-hw-addr: set-cloned MAC address to A4:34:D9:xx:xx:xx (permanent)
Nov  7 21:24:10 icarus kernel: [  210.031779] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Nov  7 21:24:10 icarus NetworkManager[1998]: <info>  [1478550250.0170] device (wlan0): supplicant interface state: disconnected -> inactive
Nov  7 21:24:10 icarus NetworkManager[1998]: <info>  [1478550250.0183] device (wlan0): supplicant interface state: inactive -> disabled
Nov  7 21:24:10 icarus NetworkManager[1998]: <info>  [1478550250.0302] device (wlan0): state change: prepare -> config (reason 'none') [40 50 0]
Nov  7 21:24:10 icarus NetworkManager[1998]: <info>  [1478550250.0304] device (wlan0): Activation: (wifi) access point 'Zeus 802.11ac' has security, but secrets are required.
Nov  7 21:24:10 icarus NetworkManager[1998]: <info>  [1478550250.0304] device (wlan0): state change: config -> need-auth (reason 'none') [50 60 0]
Nov  7 21:24:10 icarus NetworkManager[1998]: <info>  [1478550250.0350] device (wlan0): state change: need-auth -> prepare (reason 'none') [60 40 0]
Nov  7 21:24:10 icarus NetworkManager[1998]: <info>  [1478550250.0361] device (wlan0): state change: prepare -> config (reason 'none') [40 50 0]
Nov  7 21:24:10 icarus NetworkManager[1998]: <info>  [1478550250.0363] device (wlan0): Activation: (wifi) connection 'Zeus 802.11ac' has security, and secrets exist.  No new secrets needed.
Nov  7 21:24:10 icarus NetworkManager[1998]: <info>  [1478550250.0363] Config: added 'ssid' value 'Zeus 802.11ac'
Nov  7 21:24:10 icarus NetworkManager[1998]: <info>  [1478550250.0363] Config: added 'scan_ssid' value '1'
Nov  7 21:24:10 icarus NetworkManager[1998]: <info>  [1478550250.0363] Config: added 'key_mgmt' value 'WPA-PSK'
Nov  7 21:24:10 icarus NetworkManager[1998]: <info>  [1478550250.0363] Config: added 'auth_alg' value 'OPEN'
Nov  7 21:24:10 icarus NetworkManager[1998]: <info>  [1478550250.0364] Config: added 'psk' value '<omitted>'
Nov  7 21:24:10 icarus NetworkManager[1998]: <info>  [1478550250.0568] sup-iface[0x1b01140,wlan0]: config: set interface ap_scan to 1
Nov  7 21:24:10 icarus NetworkManager[1998]: <info>  [1478550250.0569] device (wlan0): supplicant interface state: disabled -> inactive
Nov  7 21:24:10 icarus NetworkManager[1998]: <info>  [1478550250.0746] device (wlan0): supplicant interface state: inactive -> scanning
Nov  7 21:24:11 icarus kernel: [  211.527123] wlan0: authenticate with aa:bb:cc:xx:xx:xx
Nov  7 21:24:11 icarus kernel: [  211.534894] wlan0: send auth to aa:bb:cc:xx:xx:xx (try 1/3)
Nov  7 21:24:11 icarus kernel: [  211.535715] wlan0: authenticated
Nov  7 21:24:11 icarus kernel: [  211.535992] wlan0: associate with aa:bb:cc:xx:xx:xx (try 1/3)
Nov  7 21:24:11 icarus kernel: [  211.537169] wlan0: RX AssocResp from aa:bb:cc:xx:xx:xx (capab=0x11 status=0 aid=2)
Nov  7 21:24:11 icarus kernel: [  211.538714] wlan0: associated
Nov  7 21:24:11 icarus kernel: [  211.538780] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Nov  7 21:24:11 icarus NetworkManager[1998]: <info>  [1478550251.5112] device (wlan0): supplicant interface state: scanning -> authenticating
Nov  7 21:24:11 icarus NetworkManager[1998]: <info>  [1478550251.5145] device (wlan0): supplicant interface state: authenticating -> associated
Nov  7 21:24:11 icarus NetworkManager[1998]: <info>  [1478550251.5672] device (wlan0): supplicant interface state: associated -> 4-way handshake
Nov  7 21:24:11 icarus NetworkManager[1998]: <info>  [1478550251.6546] device (wlan0): supplicant interface state: 4-way handshake -> completed
Nov  7 21:24:11 icarus NetworkManager[1998]: <info>  [1478550251.6547] device (wlan0): Activation: (wifi) Stage 2 of 5 (Device Configure) successful.  Connected to wireless network 'Zeus 802.11ac'.
Nov  7 21:24:11 icarus NetworkManager[1998]: <info>  [1478550251.6548] device (wlan0): state change: config -> ip-config (reason 'none') [50 70 0]
Nov  7 21:24:11 icarus NetworkManager[1998]: <info>  [1478550251.6556] dhcp4 (wlan0): activation: beginning transaction (timeout in 45 seconds)
Nov  7 21:24:11 icarus NetworkManager[1998]: <info>  [1478550251.6596] dhcp4 (wlan0): dhclient started with pid 2136
Nov  7 21:24:11 icarus NetworkManager[1998]: <info>  [1478550251.8349] dhcp4 (wlan0):   address 10.0.0.5
Nov  7 21:24:11 icarus NetworkManager[1998]: <info>  [1478550251.8350] dhcp4 (wlan0):   plen 24 (255.255.255.0)
Nov  7 21:24:11 icarus NetworkManager[1998]: <info>  [1478550251.8351] dhcp4 (wlan0):   gateway 10.0.0.1
Nov  7 21:24:11 icarus NetworkManager[1998]: <info>  [1478550251.8351] dhcp4 (wlan0):   server identifier 10.0.0.1
Nov  7 21:24:11 icarus NetworkManager[1998]: <info>  [1478550251.8351] dhcp4 (wlan0):   lease time 43200
Nov  7 21:24:11 icarus NetworkManager[1998]: <info>  [1478550251.8352] dhcp4 (wlan0):   hostname 'icarus'
Nov  7 21:24:11 icarus NetworkManager[1998]: <info>  [1478550251.8352] dhcp4 (wlan0):   nameserver '10.0.0.1'
Nov  7 21:24:11 icarus NetworkManager[1998]: <info>  [1478550251.8353] dhcp4 (wlan0):   domain name 'lan'
Nov  7 21:24:11 icarus NetworkManager[1998]: <info>  [1478550251.8353] dhcp4 (wlan0): state changed unknown -> bound
Nov  7 21:24:11 icarus NetworkManager[1998]: <info>  [1478550251.8507] device (wlan0): state change: ip-config -> ip-check (reason 'none') [70 80 0]
Nov  7 21:24:11 icarus NetworkManager[1998]: <info>  [1478550251.8529] device (wlan0): state change: ip-check -> secondaries (reason 'none') [80 90 0]
Nov  7 21:24:11 icarus NetworkManager[1998]: <info>  [1478550251.8546] device (wlan0): state change: secondaries -> activated (reason 'none') [90 100 0]
Nov  7 21:24:11 icarus NetworkManager[1998]: <info>  [1478550251.8554] manager: NetworkManager state is now CONNECTED_LOCAL
Nov  7 21:24:11 icarus NetworkManager[1998]: <info>  [1478550251.8676] manager: NetworkManager state is now CONNECTED_GLOBAL
Nov  7 21:24:11 icarus NetworkManager[1998]: <info>  [1478550251.8678] policy: set 'Zeus 802.11ac' (wlan0) as default for IPv4 routing and DNS
Nov  7 21:24:11 icarus NetworkManager[1998]: <info>  [1478550251.8702] device (wlan0): Activation: successful, device activated.
Nov  7 21:24:13 icarus NetworkManager[1998]: <info>  [1478550253.9799] dhcp6 (wlan0): activation: beginning transaction (timeout in 45 seconds)
Nov  7 21:24:13 icarus NetworkManager[1998]: <warn>  [1478550253.9801] dhcp6 (wlan0): hostname is not a FQDN, it will be ignored
Nov  7 21:24:13 icarus NetworkManager[1998]: <info>  [1478550253.9847] dhcp6 (wlan0): dhclient started with pid 2282
Nov  7 21:24:15 icarus NetworkManager[1998]: <info>  [1478550255.5868] dhcp6 (wlan0):   valid_lft 4294967295
Nov  7 21:24:15 icarus NetworkManager[1998]: <info>  [1478550255.5869] dhcp6 (wlan0):   preferred_lft 4294967295
Nov  7 21:24:15 icarus NetworkManager[1998]: <info>  [1478550255.5869] dhcp6 (wlan0):   address fdff:6934:6907::7bf
Nov  7 21:24:15 icarus NetworkManager[1998]: <info>  [1478550255.5869] dhcp6 (wlan0):   nameserver 'fe80::e66f:13ff:fe2e:bf28'
Nov  7 21:24:15 icarus NetworkManager[1998]: <info>  [1478550255.5869] dhcp6 (wlan0): state changed unknown -> bound, event ID="d9:28:xx:xx|1478550255"

Hope someone can shed some light on this.

platty · December 11, 2016, 8:10pm

I've installed OpenWrt/LEDE on 3 different DIR-860L B1 routers. On one of them I experienced similar symptoms, most noticeable on AC. I found a suggestion that flashing the stock firmware then flashing back to OpenWrt/LEDE might solve the issue and it did for me.

Here's a link to correct OEM firmware for this router:

ftp://ftp2.dlink.com/PRODUCTS/DIR-860L/REVB/DIR-860L_REVB_FIRMWARE_2.03.B03.ZIP

Link to router page in case above link doesn't work:

http://support.dlink.com/ProductInfo.aspx?m=DIR-860L

Borromini · December 11, 2016, 9:40pm

Thanks, will give that a shot. Do you recall where you found that suggestion and could you link me to that?

platty · December 12, 2016, 1:03am

I'm pretty sure I found it on the OpenWrt forum but it was months ago and I don't remember the search terms I used either, just the solution... good luck!

Edit: FWIW I struggled to pin it down since iPhones and Windows boxes didn't exhibit the symptoms much if at all. It was my *buntu rigs that were almost unusable.

Borromini · December 17, 2016, 11:45am

@platty: what networking hardware do your Ubuntu systems have?

I checked the OpenWrt forums but didn't find anything related. I have filed a bug upstream. Would be great if we could get to the bottom of this.

platty · December 17, 2016, 5:43pm

The problem affected a Haswell machine with Intel AC 3160 and a Skylake machine with Intel AC 7265, both with and without proprietary CPU microcode and iwlwifi driver. Both machines were affected using Xubuntu 15.10 and 16.04 with kernels 4.2 - 4.6.

Unfortunately, I don't have any logs to share and I can no longer reproduce the error. Because it only affected 1 of 3 routers I simply chalked it up to a 'bad flash' or 'hw bug' (but I'm no engineer). I now flash from ethernet only, just in case.

I'm currently on a custom hardened CC build right now and things are 'working'. I have handshake errors with curl (not specific to the router) but I still have one issue that hasn't been resolved - Wireless performance plumits if a USB 3.0 device is attached. This was consistent on all three routers with various USB sticks. No problems when using USB 2.0 devices. I should probably file a bug for this but I've since removed USB functionality completely just to be safe and moved all non-router/AP stuff to a Raspberry Pi.

Edit: I just recalled that I also experienced the problem on Ubuntu with a Realtek (can't recall the specific version) wireless N card in Ubuntu. Though it wasn't nearly as bad as Intel AC was. I'm totally guessing here, this could be due to the notoriously bad drivers for Realtek or an issue with wpasupplicant or NetworkManager if it is in fact a Linux specific problem.

Edit2: Did you reflash like I suggested above? Did you flash from ethernet? I'm not convinced it's an upstream kernel bug. In my case, only 1 of 3 routers exhibited the problem and it was resolved by reflashing. Also, it affected other OSes though not as dramatically. IMO, the bug should be filed with LEDE/OpenWRT if at all.

Borromini · December 17, 2016, 8:00pm

I haven't reflashed yet. At the moment, wireless is behaving exemplary, weirdly enough. Let's see how long it does.

The fact you had the same issue with two Intel clients says plenty I think. I'll see what upstream has to say.

platty · December 17, 2016, 8:35pm

I haven't reflashed yet.

Any particular reason why not?

At the moment, wireless is behaving exemplary, weirdly enough. Let's see how long it does.

Sounds familiar, 1 out of ~10 reboots of the router would work up until DHCP had to renew or I rebooted a client. Run iperf3 line of site and see if the connection drops out or becomes unstable (widely varying speeds). I've been down this same road, I'm trying to help but it seems you're ressisting for whatever reason.

The fact you had the same issue with two Intel clients says plenty I think. I'll see what upstream has to say.

Please consider linking to this thread to help upstream see the whole picture...

Borromini · December 17, 2016, 9:12pm

Well, the router's been up > 24h but only today it showed stability. I'll check with @nbd if it makes any sense to flash a manufacturer provided image (as in: does it do anything LEDE doesn't - set any NVRAM stuff etc.).

I have supplied the same info on the bug report as I posted here. You're free to add stuff, kernel devs won't really go look on another forum I think .

enri · February 10, 2017, 11:23am

I found that the 5G connection has to be in high channel like 149, otherwise, on low range like 36-44, it disconnect within a few seconds when there are traffic

My wlan card is broadcom