[G Pad 8.3 Original Android Development] pbgapski:
wifi disconnection openwrt+v500

I have made a few observations to better understand the wifi disconnections with the v500 on cm13. I will document them here as a reference.

AP: tp-link wdr3600 with openwrt 15.05 using 5GHz radio

v500: wifi always on during sleep, automatic frequency band, region code is set

Scenario: There are 20+ clients on this AP, including at least 4 cm13 and 2 cm12.1 devices (counting the v500). The v500 experiences repeated disconnections from the AP, and reconnects only when waken-up. I have checked for a few days and the v500 is the only device that gets disconnected. The AP log reads:

daemon.info hostapd: wlan1: STA XX IEEE 802.11: disassociated
daemon.info hostapd: wlan1: STA XX IEEE 802.11: deauthenticated due to inactivity (timer DEAUTH/REMOVE)

I have tried the following options on the AP side without success:

option max_inactivity '600'

option disassoc_low_ack '0'

option skip_inactivity_poll '1'

fragmentation threshold = 1584
RTS/CTS threshold = 534

Full log associated with this event:

Tue Feb 23 14:47:21 2016 daemon.info hostapd: wlan1: STA f8:a9:d0:6c:0a:b7 IEEE 802.11: deauthenticated due to inactivity (timer DEAUTH/REMOVE)

02-23 14:47:17.071 811 811 I wpa_supplicant: wlan0: WPA: Group rekeying completed with f8:1a:67:71:e8:46 [GTK=CCMP]
02-23 14:47:17.081 811 811 I wpa_supplicant: wlan0: WPA: Group rekeying completed with f8:1a:67:71:e8:46 [GTK=CCMP]
02-23 14:47:17.087 593 728 D IpReachabilityMonitor: probing ip=fe80::fa1a:67ff:fe71:e844%48
02-23 14:47:17.088 593 728 D IpReachabilityMonitor: probing ip=192.168.2.1%48
02-23 14:47:17.089 593 728 D IpReachabilityMonitor: probing ip=2804:14c:481:1225::1%48
02-23 14:47:17.090 593 2753 D NetlinkSocketObserver: NeighborEvent{elapsedMs=532967671, fe80::fa1a:67ff:fe71:e844, [(null)], RTM_NEWNEIGH, NUD_FAILED}
02-23 14:47:17.090 593 2753 W NetlinkSocketObserver: ALERT: NeighborEvent{elapsedMs=532967671, fe80::fa1a:67ff:fe71:e844, [(null)], RTM_NEWNEIGH, NUD_FAILED}
02-23 14:47:17.093 593 728 E IpReachabilityMonitor: Error probing ip=2804:14c:481:1225::1%48, errmsg=NetlinkErrorMessage{ nlmsghdr{StructNlMsgHdr{ nlmsg_len{68}, nlmsg_type{2(NLMSG_ERROR)}, nlmsg_flags{0())}, nlmsg_seq{1}, nlmsg_pid{-5922} }}, nlmsgerr{StructNlMsgErr{ error{-2}, msg{StructNlMsgHdr{ nlmsg_len{48}, nlmsg_type{28(RTM_NEWNEIGH)}, nlmsg_flags{261(NLM_F_REQUEST|NLM_F_ACK|NLM_F_ROOT))}, nlmsg_seq{1}, nlmsg_pid{0} }} }} }
02-23 14:47:17.100 593 728 D IpReachabilityMonitor: probing ip=fe80::fa1a:67ff:fe71:e844%48
02-23 14:47:17.101 593 728 E IpReachabilityMonitor: Error probing ip=fe80::fa1a:67ff:fe71:e844%48, errmsg=NetlinkErrorMessage{ nlmsghdr{StructNlMsgHdr{ nlmsg_len{68}, nlmsg_type{2(NLMSG_ERROR)}, nlmsg_flags{0())}, nlmsg_seq{1}, nlmsg_pid{-5923} }}, nlmsgerr{StructNlMsgErr{ error{-22}, msg{StructNlMsgHdr{ nlmsg_len{48}, nlmsg_type{28(RTM_NEWNEIGH)}, nlmsg_flags{261(NLM_F_REQUEST|NLM_F_ACK|NLM_F_ROOT))}, nlmsg_seq{1}, nlmsg_pid{0} }} }} }
02-23 14:47:17.101 593 728 D IpReachabilityMonitor: probing ip=192.168.2.1%48
02-23 14:47:17.102 593 728 D IpReachabilityMonitor: probing ip=2804:14c:481:1225::1%48
02-23 14:47:17.103 593 728 E IpReachabilityMonitor: Error probing ip=2804:14c:481:1225::1%48, errmsg=NetlinkErrorMessage{ nlmsghdr{StructNlMsgHdr{ nlmsg_len{68}, nlmsg_type{2(NLMSG_ERROR)}, nlmsg_flags{0())}, nlmsg_seq{1}, nlmsg_pid{-5925} }}, nlmsgerr{StructNlMsgErr{ error{-2}, msg{StructNlMsgHdr{ nlmsg_len{48}, nlmsg_type{28(RTM_NEWNEIGH)}, nlmsg_flags{261(NLM_F_REQUEST|NLM_F_ACK|NLM_F_ROOT))}, nlmsg_seq{1}, nlmsg_pid{0} }} }} }
02-23 14:47:17.111 593 2753 D NetlinkSocketObserver: NeighborEvent{elapsedMs=532967692, 192.168.2.1, [(null)], RTM_NEWNEIGH, NUD_FAILED}
02-23 14:47:17.111 593 2753 W NetlinkSocketObserver: ALERT: NeighborEvent{elapsedMs=532967692, 192.168.2.1, [(null)], RTM_NEWNEIGH, NUD_FAILED}
02-23 14:47:17.111 593 2753 W IpReachabilityMonitor: FAILURE: LOST_PROVISIONING, NeighborEvent{elapsedMs=532967692, 192.168.2.1, [(null)], RTM_NEWNEIGH, NUD_FAILED}
02-23 14:47:17.116 593 728 D IpReachabilityMonitor: clear: iface{wlan0/48}, v{7}, ntable=[]
02-23 14:47:17.136 811 811 I wpa_supplicant: wlan0: CTRL-EVENT-DISCONNECTED bssid=f8:1a:67:71:e8:46 reason=3 locally_generated=1
02-23 14:47:17.153 811 811 I wpa_supplicant: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
02-23 14:47:17.156 593 728 D WifiStateMachine: WifiStateMachine: Leaving Connected state
02-23 14:47:17.157 593 728 D IpReachabilityMonitor: clear: iface{wlan0/48}, v{8}, ntable=[]
02-23 14:47:17.157 593 728 D WifiNative-HAL: stopRssiMonitoring, cmdId 0
02-23 14:47:17.157 593 728 E WifiConfigStore: saveWifiConfigBSSID Setting BSSID for "K5"-WPA_PSK to any
02-23 14:47:17.157 593 728 E wifi_gbk2utf: g_pItemList is NULL
02-23 14:47:17.206 0 0 E [54088.924254 / 02-23 14:47:17.118] wlan: [804:E :TL ] ----> CRegion 0, hRSSI -51, Alpha 5
02-23 14:47:17.206 0 0 E [54088.924376 / 02-23 14:47:17.118] wlan: [804:E :TL ] ----> CRegion 0, hRSSI -51, Alpha 5
02-23 14:47:17.206 0 0 E [54088.926085 / 02-23 14:47:17.118] wlan: [804:E :PE ] limSendDisassocCnf: 3535: FT Preauth Session (e5238000,0) Cleanup
02-23 14:47:17.206 0 0 I : [54088.938872 / 02-23 14:47:17.128] wlan: disconnected
02-23 14:47:17.206 0 0 I : [54088.938933 / 02-23 14:47:17.128] wlan(0) 00:00:00:00:00:00 Standalone
02-23 14:47:17.206 0 0 I [54088.946898 / 02-23 14:47:17.138] cfg80211: Calling CRDA to update world regulatory domain
02-23 14:47:17.206 0 0 D : [54088.947600 / 02-23 14:47:17.138] ieee80211 phy13: info: cfg80211 reg_notifier callback for country 00
02-23 14:47:17.206 0 0 D : [54088.947661 / 02-23 14:47:17.138] ieee80211 phy13: country: BR set by driver
02-23 14:47:17.206 0 0 I [54088.947722 / 02-23 14:47:17.138] cfg80211: World regulatory domain updated:
02-23 14:47:17.206 0 0 I [54088.947752 / 02-23 14:47:17.138] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
02-23 14:47:17.223 0 0 I [54088.947783 / 02-23 14:47:17.138] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
02-23 14:47:17.233 0 0 I [54088.947844 / 02-23 14:47:17.138] cfg80211: (2457000 KHz - 2482000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
02-23 14:47:17.233 0 0 I [54088.947874 / 02-23 14:47:17.138] cfg80211: (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
02-23 14:47:17.233 0 0 I [54088.947905 / 02-23 14:47:17.138] cfg80211: (5170000 KHz - 5250000 KHz @ 80000 KHz), (300 mBi, 2000 mBm)
02-23 14:47:17.233 0 0 I [54088.947966 / 02-23 14:47:17.138] cfg80211: (5735000 KHz - 5835000 KHz @ 80000 KHz), (300 mBi, 2000 mBm)
02-23 14:47:17.234 0 0 I : [54088.947997 / 02-23 14:47:17.138] cfg80211: (57240000 KHz - 63720000 KHz @ 2160000 KHz), (N/A, 0 mBm)
02-23 14:47:17.244 593 728 E native : do suspend true
02-23 14:47:17.249 593 942 D DhcpClient: Clearing IP address
02-23 14:47:17.251 209 577 D CommandListener: Setting iface cfg
02-23 14:47:17.261 593 2755 D DhcpClient: Receive thread stopped
02-23 14:47:17.263 209 577 D CommandListener: Clearing all IP addresses on wlan0
02-23 14:47:17.349 1427 1427 D DCT : [0]onReceive: action=android.net.wifi.STATE_CHANGE
02-23 14:47:17.351 1427 1427 D DCT : [0]NETWORK_STATE_CHANGED_ACTION: mIsWifiConnected=true
02-23 14:47:17.356 593 730 D ConnectivityService: NetworkAgentInfo [WIFI () - 158] EVENT_NETWORK_INFO_CHANGED, going from CONNECTED to DISCONNECTED
02-23 14:47:17.356 593 730 D ConnectivityService: NetworkAgentInfo [WIFI () - 158] got DISCONNECTED, was satisfying 2
02-23 14:47:17.384 593 728 D WifiStateMachine: Start Disconnecting Watchdog 45
02-23 14:47:17.409 593 728 D WifiNative-HAL: stopRssiMonitoring, cmdId 0
02-23 14:47:17.412 593 730 I netstats_mobile_sample: [0,0,0,0,0,0,0,0,0,0,0,0,1456249640507]
02-23 14:47:17.413 593 607 I ProcessStatsService: Prepared write state in 10ms
02-23 14:47:17.428 593 730 I netstats_wifi_sample: [506653553,372571,10818722,121170,506621263,370960,9160185,120987,505411500,362750,15576943,224120,1456249640507]
02-23 14:47:17.431 593 728 E native : do suspend true
02-23 14:47:17.434 1427 1427 D DCT : [0]onReceive: action=android.net.wifi.STATE_CHANGE
02-23 14:47:17.436 1427 1427 D DCT : [0]NETWORK_STATE_CHANGED_ACTION: mIsWifiConnected=false
02-23 14:47:17.448 209 577 D CommandListener: Clearing all IP addresses on wlan0
02-23 14:47:17.462 1427 1427 D DCT : [0]onReceive: action=android.net.wifi.STATE_CHANGE
02-23 14:47:17.462 1427 1427 D DCT : [0]NETWORK_STATE_CHANGED_ACTION: mIsWifiConnected=false
02-23 14:47:17.466 593 730 D ConnectivityService: notifyType LOST for NetworkAgentInfo [WIFI () - 158]
02-23 14:47:17.477 811 811 E wpa_supplicant: wlan0: Failed to schedule PNO
02-23 14:47:17.482 1427 1427 D SubscriptionController: [getSubId]- sSlotIdxToSubId.size == 0, return DummySubIds slotIdx=0
02-23 14:47:17.482 1427 1427 D DctController: [TNF -2]Cellular needs Network for NetworkRequest [ id=1, legacyType=-1, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VPN] ]
02-23 14:47:17.482 1427 1427 D SubscriptionController: [getSubId]- sSlotIdxToSubId.size == 0, return DummySubIds slotIdx=0
02-23 14:47:17.483 1427 1427 D SubscriptionController: [getSubId]- sSlotIdxToSubId.size == 0, return DummySubIds slotIdx=0
02-23 14:47:17.483 1427 1427 D DctController: [TNF -2]Request not useable, pending request.
02-23 14:47:17.493 593 728 E WifiStateMachine: Fail to set up pno, want true now false
02-23 14:47:17.499 1427 1427 D DCT : [0]onReceive: action=android.net.wifi.STATE_CHANGE
02-23 14:47:17.499 1427 1427 D DCT : [0]NETWORK_STATE_CHANGED_ACTION: mIsWifiConnected=false
02-23 14:47:17.533 593 728 D WifiNetworkAgent: NetworkAgent: NetworkAgent channel lost
02-23 14:47:17.690 209 577 V IdletimerController: runCmd(/system/bin/ip6tables -w -t raw -D idletimer_raw_PREROUTING -i wlan0 -j IDLETIMER --timeout 15 --label 1 --send_nl_msg 1) res_ipv4=0, res_ipv6=0
02-23 14:47:17.779 209 577 V IdletimerController: runCmd(/system/bin/ip6tables -w -t mangle -D idletimer_mangle_POSTROUTING -o wlan0 -j IDLETIMER --timeout 15 --label 1 --send_nl_msg 1) res_ipv4=0, res_ipv6=0
02-23 14:47:17.780 912 912 W art : Long monitor contention event with owner method=boolean android.os.MessageQueue.enqueueMessage(android.os.Message, long) from MessageQueue.java:541 waiters=0 for 374ms
02-23 14:47:17.780 912 912 I dvm_lock_sample: [com.android.systemui,1,main,374,MessageQueue.java,325,-,541,74]
02-23 14:47:17.781 593 730 D CSLegacyTypeTracker: Sending DISCONNECTED broadcast for type 1 NetworkAgentInfo [WIFI () - 158] isDefaultNetwork=true
02-23 14:47:17.781 593 730 D ConnectivityService: sendStickyBroadcast: action=android.net.conn.CONNECTIVITY_CHANGE
02-23 14:47:17.781 912 1184 W art : Long monitor contention event with owner method=boolean android.os.MessageQueue.enqueueMessage(android.os.Message, long) from MessageQueue.java:541 waiters=1 for 310ms
02-23 14:47:17.781 912 1184 I dvm_lock_sample: [com.android.systemui,0,ConnectivityManager,310,MessageQueue.java,541,-,541,62]
02-23 14:47:17.783 593 611 D Tethering: MasterInitialState.processMessage what=3
02-23 14:47:17.783 1427 8330 D SubscriptionController: [getActiveSubIdList] simInfoSet=[]
02-23 14:47:17.785 1427 8330 D SubscriptionController: [getActiveSubIdList] X subIdArr.length=0
02-23 14:47:17.787 1427 2145 D SubscriptionController: [getActiveSubIdList] simInfoSet=[]
02-23 14:47:17.787 1427 2145 D SubscriptionController: [getActiveSubIdList] X subIdArr.length=0
02-23 14:47:17.786 18122 18122 I UpdateCheckReceiver: Got connectivity change, has connection: false
02-23 14:47:17.806 0 0 I [54089.032500 / 02-23 14:47:17.218] sps: BAM 0x12402000 enabled: ver:0x5, number of pipes:6
02-23 14:47:17.808 0 0 I [54089.033385 / 02-23 14:47:17.218] sps: BAM 0x12402000 enabled: ver:0x5, number of pipes:6
02-23 14:47:17.808 0 0 E wlan: [811:E :HDD] wlan_hdd_cfg80211_sched_scan_start: aborting the existing scan is unsuccessfull

If I understand what is going on, the disconnection is triggered by the client, which then fails to reconnect.