【轉】Android WiFi 常常掉線出現的幾個緣由分析！

緣由１
．從Log分析來看，這個是因爲Dhcp request fail 致使最終disconnect .

Log 分析以下： 
16:53:31.659 958 6525 D NetUtils: dhcp_do_request failed : wlan0 (renew)
08-26 16:53:31.659 958 6525 E DhcpStateMachine: DHCPV4 failed on wlan0: Timed out waiting for DHCP Renew to finish
16:53:41.568 4013 4013 D wpa_supplicant: wlan0: Deauthentication notification
16:53:41.568 4013 4013 D wpa_supplicant: Deauthentication frame IE(s) - hexdump(len=0): [NULL]
16:53:41.569 4013 4013 D wpa_supplicant: wlan0: State: COMPLETED -> DISCONNECTED
需廠商更新一個firmware ，用Attach中的firmware 從新測試。 


緣由2.
看到fail的地方都是在四次握手的時候發生的失敗 
03-06 18:23:06.585650 1024 1024 D wpa_supplicant: wlan0: State: 4WAY_HANDSHAKE -> DISCONNECTED
03-06 18:23:06.586188 749 1247 D WifiHW : [1] get event: IFNAME=wlan0 <3>WPA: 4-Way Handshake failed - pre-shared key may be incorrect
03-06 18:23:06.586198 749 1247 D WifiHW : [2] get event: IFNAME=wlan0 WPA: 4-Way Handshake failed - pre-shared key may be incorrect
失敗應該是客戶密碼輸入錯誤。若是手機仍是一直連上不，能夠把手機裏的wpa_supplicant.conf文件拉出來，看下servicecenter這個AP的密碼是否和預期的同樣

緣由３
常常reconnect是由於鏈接的AP信號太弱這時又沒有發現有信號更好的AP，致使斷線，當此AP信號稍好時又一次scan到此AP，這樣才叫reconnect；而roaming是指鏈接的AP信號太弱這時發現有信號更好的AP，鏈接到信號更好的AP，這樣叫roaming。從log_18_new這份log看到不間斷的出現：
請注意： 
像12-09 22:43:18.203 922 922 D wpa_supplicant: wlan0: State: ASSOCIATED -> COMPLETED
12-09 23:13:28.204 922 922 D wpa_supplicant: wlan0: State: COMPLETED -> DISCONNECTED
12-09 23:13:28.305 922 922 D wpa_supplicant: wlan0: State: DISCONNECTED -> SCANNING
12-09 23:13:31.015 922 922 D wpa_supplicant: wlan0: State: SCANNING -> ASSOCIATING
12-09 23:13:31.092 922 922 D wpa_supplicant: wlan0: State: ASSOCIATING -> ASSOCIATED
12-09 23:13:31.093 922 922 D wpa_supplicant: wlan0: State: ASSOCIATED -> COMPLETED
這種就是發生了disconnect，而後reconnect成功，而咱們在disconnect時間點沒有看到其餘引發斷線的trace，那就說明是firmware上報的斷線請求，能夠看到：
12-09 20:38:49.199 922 922 D wpa_supplicant: wlan0: Event INTERFACE_STATUS (5) received
12-09 20:38:49.199 922 922 D wpa_supplicant: nl80211: Event message available
12-09 20:38:49.199 922 922 D wpa_supplicant: wlan0: Event DISASSOC (1) received
12-09 20:38:49.199 922 922 D wpa_supplicant: wlan0: Disassociation notification
而firmware上報斷線的緣由只有一種，就是它認爲RSSI太弱了 
像12-10 04:37:40.633 922 922 D wpa_supplicant: wlan0: State: ASSOCIATED -> COMPLETED
12-10 05:09:43.609 922 922 D wpa_supplicant: wlan0: State: COMPLETED -> ASSOCIATED
12-10 05:09:43.609 922 922 D wpa_supplicant: wlan0: State: ASSOCIATED -> COMPLETED

這種就是發生了roaming，發生roaming的前提就是發現當前AP信號較弱，同時scan到了信號更好的AP．

緣由４：
從log來看是AP要求設備斷線的： 
09-06 10:48:56.919 <3>[ 1555.321037] (1)[3319:tx_thread][wlan] Rx Deauth frame from BSSID=[aa:63:df:5c:db:c5].
09-06 10:48:56.919 <3>[ 1555.321093] (1)[3319:tx_thread][wlan] Reason code = 7

緣由５：
log中看到斷線緣由以下，是AP更改了security，致使斷線 
04-20 11:32:37.439 <4>[ 3273.328514]<2> (1)[4122:tx_thread][wlan] rsnCheckSecurityModeChanged: (RSN INFO) security change, WPA2->WEP
04-20 11:32:37.439 <4>[ 3273.328530]<2> (1)[4122:tx_thread][wlan] scanProcessBeaconAndProbeResp: (SCN INFO) Beacon security mode change detected
04-20 11:32:37.439 <4>[ 3273.328544]<2> (1)[4122:tx_thread][wlan] aisFsmStateAbort_NORMAL_TR: (INIT INFO) aisFsmStateAbort_NORMAL_TR
04-20 11:32:37.439 <4>[ 3273.328559]<2> (1)[4122:tx_thread][wlan] aisFsmDisconnect: (INIT INFO) aisFsmDisconnect

有兩次斷開鏈接的狀況，具體以下 
28191 04-09 18:39:16.715 3889 3889 D wpa_supplicant: nl80211: Associated on 2422 MHz
28192 04-09 18:39:16.715 3889 3889 D wpa_supplicant: nl80211: Associated with 10:0e:0e:20:61:15
發送roaming，斷開與10:0e:0e:20:61:15的鏈接，從新鏈接另外一個AP:10:0e:0e:20:5e:7d
33517 04-09 18:39:43.054 3889 3889 D wpa_supplicant: nl80211: Drv Event 47 (NL80211_CMD_ROAM) received for wlan0
33518 04-09 18:39:43.054 3889 3889 D wpa_supplicant: nl80211: Roam event
33519 04-09 18:39:43.054 3889 3889 D wpa_supplicant: nl80211: Associated on 2472 MHz
33520 04-09 18:39:43.054 3889 3889 D wpa_supplicant: nl80211: Associated with 10:0e:0e:20:5e:7d
33521 04-09 18:39:43.054 3889 3889 D wpa_supplicant: nl80211: Operating frequency for the associated BSS from scan results: 2472 MHz
33543 04-09 18:39:43.055 3889 3889 D wpa_supplicant: Operating frequency changed from 2422 to 2472 MHz
33544 04-09 18:39:43.055 3889 3889 D wpa_supplicant: nl80211: Associated on 2472 MHz
33545 04-09 18:39:43.055 3889 3889 D wpa_supplicant: nl80211: Associated with 10:0e:0e:20:5e:7d
33546 04-09 18:39:43.055 3889 3889 D wpa_supplicant: nl80211: Received scan results (1 BSSes)
33549 04-09 18:39:43.055 3889 3889 D wpa_supplicant: wlan0: State: COMPLETED -> ASSOCIATED
上層send disable network command,10:0e:0e:20:5e:7d斷開鏈接
39804 04-09 18:40:07.283 3889 3889 D wpa_supplicant: wlan0: Control interface command 'DISABLE_NETWORK 1'
39805 04-09 18:40:07.283 3889 3889 D wpa_supplicant: CTRL_IFACE: DISABLE_NETWORK id=1
39806 04-09 18:40:07.283 3889 3889 D wpa_supplicant: wlan0: Request to deauthenticate - bssid=10:0e:0e:20:5e:7d pending_bssid=00:00:00:00:00:00 reason=3 state=COMPLETED
39808 04-09 18:40:07.283 3889 3889 D wpa_supplicant: wpa_driver_nl80211_disconnect(reason_code=3)
39817 04-09 18:40:07.298 3889 3889 D wpa_supplicant: wlan0: Event DEAUTH (12) received
39832 04-09 18:40:07.299 3889 3889 D wpa_supplicant: addr=10:0e:0e:20:5e:7d

39833 04-09 18:40:07.299 3889 3889 D wpa_supplicant: wlan0: State: COMPLETED -> DISCONNECTED

log2:

此問題從目前的Log分析來看，是因爲這個Ap發了一個Deatuh的 Frame ，致使disconnect ，所以是Ap的行爲。從新換Ap測試下。
Log分析以下： 
mainlog : 
08-24 11:24:15.410 1097 1097 D wpa_supplicant: nl80211: Drv Event 48 (NL80211_CMD_DISCONNECT) received for wlan0
08-24 11:24:15.410 1097 1097 D wpa_supplicant: nl80211: Disconnect event
08-24 11:24:15.410 1097 1097 D wpa_supplicant: wlan0: Event DEAUTH (12) received
08-24 11:24:15.410 1097 1097 D wpa_supplicant: wlan0: Deauthentication notification
08-24 11:24:15.410 1097 1097 D wpa_supplicant: wlan0: * reason 101
08-24 11:24:15.410 1097 1097 D wpa_supplicant: Deauthentication frame IE(s) - hexdump(len=0): [NULL]
08-24 11:24:15.410 1097 1097 I wpa_supplicant: wlan0: CTRL-EVENT-DISCONNECTED bssid=42:0e:0e:20:6a:d2 reason=101
08-24 11:24:15.410 1097 1097 D wpa_supplicant: wlan0: Disconnect event - remove keys
08-24 11:24:15.411 715 1217 D WifiMonitor: Event [IFNAME=wlan0 CTRL-EVENT-DISCONNECTED bssid=42:0e:0e:20:6a:d2 reason=101]
08-24 11:24:15.412 715 1217 E WifiMonitor: WifiMonitor notify network disconnect: null reason=0
08-24 11:24:15.420 1097 1097 D wpa_supplicant: wlan0: State: COMPLETED -> DISCONNECTED
從上面能夠看出是因爲收到了；discon因此致使斷線！ 
而從kernellog 對應來分析： 
08-24 11:24:15.380 <4>[ 8153.620603]<0>-(0)[936:tx_thread][wlan] nicTxReleaseResource: (TX STATE) Release: TC4 count 1, Free=4; TC5 count 0, Free=2
08-24 11:24:15.395 <4>[ 8153.635513]<0> (0)[936:tx_thread][wlan] saaFsmRunEventRxDeauth: (SAA INFO) Rx Deauth frame from BSSID=[42:0e:0e:20:6a:d2].
08-24 11:24:15.395 <4>[ 8153.635553]<0> (0)[936:tx_thread][wlan] saaFsmRunEventRxDeauth: (SAA INFO) Deauth reason = 101
08-24 11:24:15.395 <4>[ 8153.635912]<0> (0)[936:tx_thread][wlan] nicMediaStateChange: (INIT TRACE) DisByMC
08-24 11:24:15.395 <4>[ 8153.635970]<0> (0)[936:tx_thread][wlan] kalIndicateStatusAndComplete: (INIT INFO) [wifi] wlan0 netif_carrier_off 2
08-24 11:24:15.399 <4>[ 8153.639801]<0> (0)[936:tx_thread][wlan] kalIndicateStatusAndComplete: (INIT INFO) [wifi] wlan0 cfg80211_disconnected
08-24 11:24:15.399 <6>[ 8153.639876]<0> (0)[12175:kworker/0:1][mtk_net][sched]dev_deactivate dev = wlan0
08-24 11:24:15.399 <4>[ 8153.640014]<0> (0)[936:tx_thread][wlan] aisFsmSteps: (AIS STATE) [13] TRANSITION: [10] -> [0]
從上面能夠看出是：手機收到了Rx Deauth frame from BSSID=[42:0e:0e:20:6a:d2]. 從而致使斷線。
所以此問題從上面Log具體來分析是Ap的行爲。

 

緣由６：
從kernel log能夠看到，wlan driver在數據傳輸測試中，由於系統memory過低，alloc skb buffer一直失敗，482~517一直印出下面的backtrace：
<4>[ 482.458525] (2)[5:kworker/u:0]CPU 1: hi: dump_backtrace+0x0/0 77
<4>[ 482.458539] (3)[2576:tx_thread][<c00122a8>] (dump_backtrace+0x0/0x10c) from [<c06e004c>] (dump_stack+0x18/0x1c)
<4>[ 482.458550] (3)[2576:tx_thread] r6:ddf5c000 r5:00000000 r4:00000020CP3:c0996244 r3:c0996244
<4>[ 482.458577] (2)[5:kworker/u:0]CPU 3: hi: 186, btch: 31 usd: 59
<4>[ 482.458590] (3)[2576:tx_thread][<c06e0034>] (dump_stack+0x0/0x1c) from [<c00d24e0>] (warn_alloc_failed+0xd0/0x114)
<4>[ 482.458611] (3)[2576:tx_thread][<c00d2410>] (warn_alloc_failed+0x0/0x114) from [<c00d4390>] (__alloc_pages_nodemask+0x3c4/0x828)
<4>[ 482.458627] (2)[5:kworker/u:0]active_anon:22059 inactive_anon:22130 isolated_anon:0
<4>[ 482.458634] (2)[5:kworker/u:0] active_file:11548 inactive_file:31936 isolated_file:0
<4>[ 482.458640] (2)[5:kworker/u:0] unevictable:1190 dirty:14552 writeback:2556 unstable:0
<4>[ 482.458646] (2)[5:kworker/u:0] free:255 slab_reclaimable:4501 slab_unreclaimable:6252
<4>[ 482.458653] (2)[5:kworker/u:0] mapped:5965 shmem:127 pagetables:2348 bounce:0
<4>[ 482.458671] (3)[2576:tx_thread] r3:00000000Normal free:1020kB min:2804kB low:8304kB high:9004kB active_anon:88236kB inactive_anon:88520kB active_file:46192kB inactive_file:127744kB unevictable:4760kB isolated(anon):0kB isolated(file):0kB present:492140kB mlocked:3004kB dirty:58208kB writeback:10224kB mapped:23860kB shmem:508kB slab_reclaimable:18004kB slab_unreclaimable:25008kB kernel_stack:6384kB pagetables:9392kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:61 all_unreclaimable? no 
<4>[ 482.458708] (2)[5:kworker/u:0]lowmem_reserve[]: 0 0 0
<4>[ 482.458721] (2)[5:kworker/u:0]Normal: 252:00000000 r2:00000000
<4>[ 482.458735] (3)[2576:tx_thread] r7:c09ad010 r6:00000000 r5:000000300*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 1020kB
<4>[ 482.458774] (2)[5:kworker/u:0]44377 total pagecache pages
<4>[ 482.458782] (2)[5:kworker/u:0]249 pages in swap cache
<4>[ 482.458792] (2)[5:kworker/u:0]Swa:00000000 r4:00000000
<4>[ 482.458804] (2)[5:kworker/u:0]Free swap = 375288kB
<4>[ 482.458816] (3)[2576:tx_thread][<c00d3fcc>] (__alloc_pages_nodemask+0x0/0x828) from [<c00feb88>] (new_slab+0x1f0/0x21c)
<4>[ 482.458830] (2)[5:kworker/u:0]Total swap = 393212kB
<4>[ 482.458844] (3)[2576:tx_thread][<c00fe998>] (new_slab+0x0/0x21c) from [<c06e2ac8>] (__slab_alloc.isra.51.constprop.55+0x514/0x534)
<4>[ 482.458861] (2)[5:kworker/u:0]SLUB: Unable to allocate memory on node -1 (gfp=0x20)
<4>[ 482.458875] (3)[2576:tx_thread][<c06e25b4>] (__slab_alloc.isra.51.constprop.55+0x0/0x534) from [<c010005c>] (__kmalloc_track_caller+0x10c/0x160)
<4>[ 482.458899] (3)[2576:tx_thread][<c00fff50>] (__kmalloc_track_caller+0x0/0x160) from [<c059fa30>] (__alloc_skb+0x58/0xf4)
<4>[ 482.458910] (2)[5:kworker/u:0] cache: kmalloc-2048, object size: 2048, buffer size: 2048, default order: 0, min order: 0
<4>[ 482.458922] (2)[5:kworker/u:0] node 0: slabs: 0, objs: 0, free: 0
<4>[ 482.458946] (3)[2576:tx_thread][<c059f9d8>] (__alloc_skb+0x0/0xf4) from [<c059faec>] (dev_alloc_skb+0x20/0x44)
<4>[ 482.458973] (3)[2576:tx_thread][<c059facc>] (dev_alloc_skb+0x0/0x44) from [<c042b4a8>] (kalPacketAlloc+0x18/0x28)
<4>[ 482.459005] (3)[2576:tx_thread]kworker/u:0: page allocation failure: order:0, mode:0x20
<4>[ 482.459014] (2)[5:kworker/u:0]kworker/u:0: page allocation failure: order:0, mode:0x20
<4>[ 482.459023] (2)[5:kworker/u:0]Backtrace:
<4>[ 482.459034] (3)[2576:tx_thread] r4:e226a4c0[<c00122a8>] (dump_backtrace+0x0/0x10c) from [<c06e004c>] (dump_stack+0x18/0x1c)
<4>[ 482.459054] (2)[5:kworker/u:0] r6:ddc32000 r3:000042f0
<4>[ 482.459067] (2)[5:kworker/u:0] r5:00000000[<c041a470>] (nicRxSetupRFB+0x0/0xf4) from [<c03f93b0>] (wlanReturnPacket+0xc4/0x26c)
<4>[ 482.459087] (3)[2576:tx_thread] r5:000042f0 r4:e226a4c0
<4>[ 482.459101] (2)[5:kworker/u:0] r4:00000020[<c03f92ec>] (wlanReturnPacket+0x0/0x26c) from [<c042b650>] (kalRxIndicatePkts+0x168/0x298)
<4>[ 482.459120] (3)[2576:tx_thread] r7:d72b0000 r6:e2212b7c r5:dd3602e0 r3:00000000 r4:ce9d9e40
<4>[ 482.459143] (3)[2576:tx_thread] 
<4>[ 482.459154] (2)[5:kworker/u:0][<c06e0034>] (dump_stack+0x0/0x1c) from [<c00d24e0>] (warn_alloc_failed+0xd0/0x114)
<4>[ 482.459175] (2)[5:kworker/u:0][<c00d2410>] (warn_alloc_failed+0x0/0x114) from [<c00d4390>] (__alloc_pages_nodemask+0x3c4/0x828)
<4>[ 482.459191] (3)[2576:tx_thread][<c042b4e8>] (kalRxIndicatePkts+0x0/0x298) from [<c041c2e8>] (nicRxProcessRFBs+0x1e8/0x294)
<4>[ 482.459206] (2)[5:kworker/u:0] r3:00000000[<c041c100>] (nicRxProcessRFBs+0x0/0x294) from [<c041c79c>] (nicProcessRxInterrupt+0x24/0x5c)
<4>[ 482.459229] (2)[5:kworker/u:0] r2:00000000[<c041c778>] (nicProcessRxInterrupt+0x0/0x5c) from [<c0411d5c>] (nicProcessIST_impl+0x64/0x1b4)
最後FreeSwRfb在518時耗盡，這個時間點正好是tcpdump顯示PC端沒有迴應的開始： 
<4>[ 518.094029] (1)[2576:tx_thread][wlan] qmHandleRxPackets: (QM TRACE) Mark NULL the Packet for less Free Sw Rfb
<4>[ 518.094055] (1)[2576:tx_thread][wlan] qmHandleRxPackets: (QM TRACE) Mark NULL the Packet for less Free Sw Rfb
<4>[ 518.094281] (1)[2576:tx_thread][wlan] qmHandleRxPackets: (QM TRACE) Mark NULL the Packet for less Free Sw Rfb
<4>[ 518.094329] (1)[2576:tx_thread][wlan] qmHandleRxPackets: (QM TRACE) Mark NULL the Packet for less Free Sw Rfb
<4>[ 518.094379] (1)[2576:tx_thread][wlan] qmHandleRxPackets: (QM TRACE) Mark NULL the Packet for less Free Sw Rfb
<4>[ 518.094395] (1)[2576:tx_thread][wlan] qmHandleRxPackets: (QM TRACE) Mark NULL the Packet for less Free Sw Rfb
<4>[ 518.094442] (1)[2576:tx_thread][wlan] qmHandleRxPackets: (QM TRACE) Mark NULL the Packet for less Free Sw Rfb
<4>[ 518.094601] (1)[2576:tx_thread][wlan] qmHandleRxPackets: (QM TRACE) Mark NULL the Packet for less Free Sw Rfb
<4>[ 518.094648] (1)[2576:tx_thread][wlan] qmHandleRxPackets: (QM TRACE) Mark NULL the Packet for less Free Sw Rfb
<4>[ 518.094697] (1)[2576:tx_thread][wlan] qmHandleRxPackets: (QM TRACE) Mark NULL the Packet for less Free Sw Rfb
<4>[ 518.094714] (1)[2576:tx_thread][wlan] qmHandleRxPackets: (QM TRACE) Mark NULL the Packet for less Free Sw Rfb
<4>[ 518.094762] (1)[2576:tx_thread][wlan] qmHandleRxPackets: (QM TRACE) Mark NULL the Packet for less Free Sw Rfb

原文連接： https://blog.csdn.net/chi_wy/article/details/50963279