search

espressif / esp-idf

Espressif IoT Development Framework. Official development framework for Espressif SoCs.
Apache License 2.0
13.63k stars 7.28k forks source link

WiFi randomly disconnect from AP with disconnect reason WIFI_REASON_ASSOC_LEAVE (IDFGH-4044) #5915

Closed AxelLin closed 3 years ago

AxelLin commented 4 years ago

Environment

Problem Description

This seems happen randomly when I test with join TP-LINK TL-WR1043ND AP. From below log, the RSSI is prettyr good.

I (4194) wifi:wifi driver task: 3ffc6870, prio:23, stack:6656, core=0 I (4214) wifi:wifi firmware version: d3be909 I (4214) wifi:wifi certification version: v7.0 I (4214) wifi:config NVS flash: enabled I (4215) wifi:config nano formating: disabled I (4219) wifi:Init data frame dynamic rx buffer num: 32 I (4224) wifi:Init management frame dynamic rx buffer num: 32 I (4229) wifi:Init management short buffer num: 32 I (4234) wifi:Init dynamic tx buffer num: 32 I (4238) wifi:Init static rx buffer size: 1600 I (4242) wifi:Init static rx buffer num: 10 I (4246) wifi:Init dynamic rx buffer num: 32 I (13875) wifi:set country: cc=US schan=1 nchan=11 policy=0 I (13982) wifi:mode : sta (f0:08:d1:79:8c:28) I (14711) wifi:new:<6,2>, old:<1,0>, ap:<255,255>, sta:<6,2>, prof:1 I (15351) wifi:state: init -> auth (b0) I (15357) wifi:state: auth -> assoc (0) I (15380) wifi:state: assoc -> run (10) I (15401) wifi:connected with TEST-AP, aid = 3, channel 6, 40D, bssid = 18:a6:f7:ab:ca:66 I (15402) wifi:security: WPA2-PSK, phy: bgn, rssi: -43 I (15404) wifi:pm start, type: 1 I (15469) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (16217) wifi:Set ps type: 1 I (253848) wifi:state: run -> init (ce00) I (253850) wifi:pm stop, total sleep time: 184541140 us / 238443301 us I (253851) wifi:new:<6,0>, old:<6,2>, ap:<255,255>, sta:<6,2>, prof:1

Check with disconnected->reason, it's 8 (WIFI_REASON_ASSOC_LEAVE)

Expected Behavior

Should not disconnect from AP randomly.

Actual Behavior

Disconnect from AP with WIFI_REASON_ASSOC_LEAVE.

Steps to reproduce

Just join an AP and wait... (it happens at random time so sometimes need to wait longer time)

AxelLin commented 4 years ago

Below shows the log the device disconnect from AP several times.

I (4182) wifi:wifi driver task: 3ffc68dc, prio:23, stack:6656, core=0 I (4202) wifi:wifi firmware version: d3be909 I (4202) wifi:wifi certification version: v7.0 I (4202) wifi:config NVS flash: enabled I (4203) wifi:config nano formating: disabled I (4207) wifi:Init data frame dynamic rx buffer num: 32 I (4212) wifi:Init management frame dynamic rx buffer num: 32 I (4217) wifi:Init management short buffer num: 32 I (4222) wifi:Init dynamic tx buffer num: 32 I (4226) wifi:Init static rx buffer size: 1600 I (4230) wifi:Init static rx buffer num: 10 I (4234) wifi:Init dynamic rx buffer num: 32 I (4238) wifi_init: rx ba win: 6 I (4241) wifi_init: tcpip mbox: 32 I (4246) wifi_init: udp mbox: 6 I (4249) wifi_init: tcp mbox: 6 I (4253) wifi_init: tcp tx win: 5744 I (4257) wifi_init: tcp rx win: 5744 I (4262) wifi_init: tcp mss: 1440 I (4266) wifi_init: WiFi IRAM OP enabled I (4270) wifi_init: WiFi RX IRAM OP enabled I (13853) wifi:set country: cc=US schan=1 nchan=11 policy=0 I (13960) wifi:mode : sta (f0:08:d1:79:8c:28) I (14690) wifi:new:<6,2>, old:<1,0>, ap:<255,255>, sta:<6,2>, prof:1 I (15329) wifi:state: init -> auth (b0) I (15348) wifi:state: auth -> assoc (0) I (15363) wifi:state: assoc -> run (10) I (15373) wifi:connected with TEST-AP, aid = 1, channel 6, 40D, bssid = 18:a6:f7:ab:ca:66 I (15373) wifi:security: WPA2-PSK, phy: bgn, rssi: -39 I (15375) wifi:pm start, type: 1 I (15445) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (16206) wifi:Set ps type: 1 I (3578929) wifi:state: run -> init (ce00) I (3579099) wifi:new:<6,2>, old:<6,0>, ap:<255,255>, sta:<6,2>, prof:1 I (3579103) wifi:state: init -> auth (b0) I (3579128) wifi:state: auth -> assoc (0) I (3579182) wifi:state: assoc -> run (10) I (3579197) wifi:connected with TEST-AP, aid = 1, channel 6, 40D, bssid = 18:a6:f7:ab:ca:66 I (3579199) wifi:security: WPA2-PSK, phy: bgn, rssi: -31 I (3579202) wifi:pm start, type: 1 I (3579236) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (3580207) wifi:Set ps type: 1 I (4700114) wifi:state: run -> init (ce00) I (4700117) wifi:pm stop, total sleep time: 1054343312 us / 1120904987 us I (4700117) wifi:new:<6,0>, old:<6,2>, ap:<255,255>, sta:<6,2>, prof:1 I (4700266) wifi:new:<6,2>, old:<6,0>, ap:<255,255>, sta:<6,2>, prof:1 I (4700268) wifi:state: init -> auth (b0) I (4700288) wifi:state: auth -> assoc (0) I (4700304) wifi:state: assoc -> run (10) I (4700312) wifi:connected with TEST-AP, aid = 1, channel 6, 40D, bssid = 18:a6:f7:ab:ca:66 I (4700313) wifi:security: WPA2-PSK, phy: bgn, rssi: -38 I (4700315) wifi:pm start, type: 1 I (4700391) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (4700392) wifi:state: run -> init (ce00) I (4700393) wifi:pm stop, total sleep time: 0 us / 75236 us I (4700395) wifi:new:<6,0>, old:<6,2>, ap:<255,255>, sta:<6,2>, prof:1 I (4700547) wifi:new:<6,2>, old:<6,0>, ap:<255,255>, sta:<6,2>, prof:1 I (4700549) wifi:state: init -> auth (b0) I (4700552) wifi:state: auth -> assoc (0) I (4700563) wifi:state: assoc -> run (10) I (4700572) wifi:connected with TEST-AP, aid = 1, channel 6, 40D, bssid = 18:a6:f7:ab:ca:66 I (4700573) wifi:security: WPA2-PSK, phy: bgn, rssi: -37 I (4700575) wifi:pm start, type: 1 I (4700598) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (4701207) wifi:Set ps type: 1 I (8496342) wifi:state: run -> init (ce00) I (8496345) wifi:pm stop, total sleep time: 3567685118 us / 3795766526 us I (8496346) wifi:new:<6,0>, old:<6,2>, ap:<255,255>, sta:<6,2>, prof:1 I (8496495) wifi:new:<6,2>, old:<6,0>, ap:<255,255>, sta:<6,2>, prof:1 I (8496497) wifi:state: init -> auth (b0) I (8496500) wifi:state: auth -> assoc (0) I (8496511) wifi:state: assoc -> run (10) I (8496519) wifi:connected with TEST-AP, aid = 1, channel 6, 40D, bssid = 18:a6:f7:ab:ca:66 I (8496520) wifi:security: WPA2-PSK, phy: bgn, rssi: -33 I (8496522) wifi:pm start, type: 1 I (8496546) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (8497208) wifi:Set ps type: 1 I (10876792) wifi:state: run -> init (ce00) I (10876794) wifi:pm stop, total sleep time: 2235644704 us / 2380268946 us I (10876795) wifi:new:<6,0>, old:<6,2>, ap:<255,255>, sta:<6,2>, prof:1 I (10876944) wifi:new:<6,2>, old:<6,0>, ap:<255,255>, sta:<6,2>, prof:1 I (10876947) wifi:state: init -> auth (b0) I (10876950) wifi:state: auth -> assoc (0) I (10876961) wifi:state: assoc -> run (10) I (10876969) wifi:connected with TEST-AP, aid = 1, channel 6, 40D, bssid = 18:a6:f7:ab:ca:66 I (10876970) wifi:security: WPA2-PSK, phy: bgn, rssi: -34 I (10876973) wifi:pm start, type: 1 I (10876996) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (10877708) wifi:Set ps type: 1 I (10900709) wifi:state: run -> init (ce00) I (10900712) wifi:pm stop, total sleep time: 20700834 us / 23735831 us I (10900712) wifi:new:<6,0>, old:<6,2>, ap:<255,255>, sta:<6,2>, prof:1 I (10900862) wifi:new:<6,2>, old:<6,0>, ap:<255,255>, sta:<6,2>, prof:1 I (10900864) wifi:state: init -> auth (b0) I (10900867) wifi:state: auth -> assoc (0) I (10900879) wifi:state: assoc -> run (10) I (10900888) wifi:connected with TEST-AP, aid = 1, channel 6, 40D, bssid = 18:a6:f7:ab:ca:66 I (10900888) wifi:security: WPA2-PSK, phy: bgn, rssi: -34 I (10900891) wifi:pm start, type: 1 I (10900913) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (10901708) wifi:Set ps type: 1 I (10901822) wifi:state: run -> init (ce00) I (10901824) wifi:pm stop, total sleep time: 295782 us / 929679 us I (10901824) wifi:new:<6,0>, old:<6,2>, ap:<255,255>, sta:<6,2>, prof:1 I (10901974) wifi:new:<6,2>, old:<6,0>, ap:<255,255>, sta:<6,2>, prof:1 I (10901976) wifi:state: init -> auth (b0) I (10901979) wifi:state: auth -> assoc (0) I (10901990) wifi:state: assoc -> run (10) I (10902004) wifi:connected with TEST-AP, aid = 1, channel 6, 40D, bssid = 18:a6:f7:ab:ca:66 I (10902005) wifi:security: WPA2-PSK, phy: bgn, rssi: -33 I (10902007) wifi:pm start, type: 1 I (10902029) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (10902708) wifi:Set ps type: 1 I (10936099) wifi:state: run -> init (ce00) I (10936101) wifi:pm stop, total sleep time: 31050673 us / 34091067 us I (10936102) wifi:new:<6,0>, old:<6,2>, ap:<255,255>, sta:<6,2>, prof:1 I (10936252) wifi:new:<6,2>, old:<6,0>, ap:<255,255>, sta:<6,2>, prof:1 I (10936254) wifi:state: init -> auth (b0) I (10936257) wifi:state: auth -> assoc (0) I (10936268) wifi:state: assoc -> run (10) I (10936285) wifi:connected with TEST-AP, aid = 1, channel 6, 40D, bssid = 18:a6:f7:ab:ca:66 I (10936285) wifi:security: WPA2-PSK, phy: bgn, rssi: -33 I (10936288) wifi:pm start, type: 1 I (10936303) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (10937208) wifi:Set ps type: 1 I (10957471) wifi:state: run -> init (ce00) I (10957474) wifi:pm stop, total sleep time: 18693799 us / 21182796 us I (10957475) wifi:new:<6,0>, old:<6,2>, ap:<255,255>, sta:<6,2>, prof:1 I (10957624) wifi:new:<6,2>, old:<6,0>, ap:<255,255>, sta:<6,2>, prof:1 I (10957626) wifi:state: init -> auth (b0) I (10957629) wifi:state: auth -> assoc (0) I (10957640) wifi:state: assoc -> run (10) I (10957662) wifi:connected with TEST-AP, aid = 1, channel 6, 40D, bssid = 18:a6:f7:ab:ca:66 I (10957662) wifi:security: WPA2-PSK, phy: bgn, rssi: -39 I (10957665) wifi:pm start, type: 1 I (10957676) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (10958708) wifi:Set ps type: 1 I (11049704) wifi:state: run -> init (ce00) I (11049706) wifi:pm stop, total sleep time: 83650518 us / 92037905 us I (11049707) wifi:new:<6,0>, old:<6,2>, ap:<255,255>, sta:<6,2>, prof:1 I (11049857) wifi:new:<6,2>, old:<6,0>, ap:<255,255>, sta:<6,2>, prof:1 I (11049859) wifi:state: init -> auth (b0) I (11049864) wifi:state: auth -> assoc (0) I (11049880) wifi:state: assoc -> run (10) I (11049897) wifi:connected with TEST-AP, aid = 1, channel 6, 40D, bssid = 18:a6:f7:ab:ca:66 I (11049897) wifi:security: WPA2-PSK, phy: bgn, rssi: -33 I (11049900) wifi:pm start, type: 1 I (11049907) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (11050708) wifi:Set ps type: 1 I (11103526) wifi:state: run -> init (ce00) I (11103528) wifi:pm stop, total sleep time: 49335080 us / 53625622 us I (11103529) wifi:new:<6,0>, old:<6,2>, ap:<255,255>, sta:<6,2>, prof:1 I (11103679) wifi:new:<6,2>, old:<6,0>, ap:<255,255>, sta:<6,2>, prof:1 I (11103681) wifi:state: init -> auth (b0) I (11103684) wifi:state: auth -> assoc (0) I (11103695) wifi:state: assoc -> run (10) I (11103704) wifi:connected with TEST-AP, aid = 1, channel 6, 40D, bssid = 18:a6:f7:ab:ca:66 I (11103704) wifi:security: WPA2-PSK, phy: bgn, rssi: -32 I (11103707) wifi:pm start, type: 1 I (11103730) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (11104707) wifi:Set ps type: 1 I (11104955) wifi:state: run -> init (ce00) I (11104958) wifi:pm stop, total sleep time: 517295 us / 1247963 us I (11104959) wifi:new:<6,0>, old:<6,2>, ap:<255,255>, sta:<6,2>, prof:1 I (11105108) wifi:new:<6,2>, old:<6,0>, ap:<255,255>, sta:<6,2>, prof:1 I (11105110) wifi:state: init -> auth (b0) I (11105115) wifi:state: auth -> assoc (0) I (11105128) wifi:state: assoc -> run (10) I (11105138) wifi:connected with TEST-AP, aid = 1, channel 6, 40D, bssid = 18:a6:f7:ab:ca:66 I (11105139) wifi:security: WPA2-PSK, phy: bgn, rssi: -34 I (11105141) wifi:pm start, type: 1 I (11105164) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (11106220) wifi:Set ps type: 1 I (11108741) wifi:state: run -> init (ce00) I (11108744) wifi:pm stop, total sleep time: 2643121 us / 3599355 us I (11108744) wifi:new:<6,0>, old:<6,2>, ap:<255,255>, sta:<6,2>, prof:1 I (11108894) wifi:new:<6,2>, old:<6,0>, ap:<255,255>, sta:<6,2>, prof:1 I (11108896) wifi:state: init -> auth (b0) I (11108899) wifi:state: auth -> assoc (0) I (11108924) wifi:state: assoc -> run (10) I (11108967) wifi:connected with TEST-AP, aid = 1, channel 6, 40D, bssid = 18:a6:f7:ab:ca:66 I (11108968) wifi:security: WPA2-PSK, phy: bgn, rssi: -38 I (11108970) wifi:pm start, type: 1 I (11109048) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (11109708) wifi:Set ps type: 1 I (12175625) wifi:state: run -> init (ce00) I (12175628) wifi:pm stop, total sleep time: 1001171760 us / 1066654421 us I (12175629) wifi:new:<6,0>, old:<6,2>, ap:<255,255>, sta:<6,2>, prof:1 I (12175778) wifi:new:<6,2>, old:<6,0>, ap:<255,255>, sta:<6,2>, prof:1 I (12175780) wifi:state: init -> auth (b0) I (12175783) wifi:state: auth -> assoc (0) I (12175794) wifi:state: assoc -> run (10) I (12175803) wifi:connected with TEST-AP, aid = 1, channel 6, 40D, bssid = 18:a6:f7:ab:ca:66 I (12175803) wifi:security: WPA2-PSK, phy: bgn, rssi: -32 I (12175806) wifi:pm start, type: 1 I (12175829) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (12176707) wifi:Set ps type: 1 I (12176713) wifi:I (12176715) BLE_GW: local server is already started I (12176725) wifi:pm stop, total sleep time: 287743 us / 916329 us I (12176742) wifi:new:<6,0>, old:<6,2>, ap:<255,255>, sta:<6,2>, prof:1 I (12176894) wifi:new:<6,2>, old:<6,0>, ap:<255,255>, sta:<6,2>, prof:1 I (12176896) wifi:state: init -> auth (b0) I (12176903) wifi:state: auth -> assoc (0) I (12176916) wifi:state: assoc -> run (10) I (12176924) wifi:connected with TEST-AP, aid = 1, channel 6, 40D, bssid = 18:a6:f7:ab:ca:66 I (12176925) wifi:security: WPA2-PSK, phy: bgn, rssi: -37 I (12176928) wifi:pm start, type: 1 I (12177014) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (12177708) wifi:Set ps type: 1 I (12177781) wifi:state: run -> init (ce00) I (12177782) wifi:pm stop, total sleep time: 268130 us / 851440 us I (12177783) wifi:new:<6,0>, old:<6,2>, ap:<255,255>, sta:<6,2>, prof:1 I (12177933) wifi:new:<6,2>, old:<6,0>, ap:<255,255>, sta:<6,2>, prof:1 I (12177935) wifi:state: init -> auth (b0) I (12177941) wifi:state: auth -> assoc (0) I (12177952) wifi:state: assoc -> run (10) I (12177961) wifi:connected with TEST-AP, aid = 1, channel 6, 40D, bssid = 18:a6:f7:ab:ca:66 I (12177961) wifi:security: WPA2-PSK, phy: bgn, rssi: -31 I (12177964) wifi:pm start, type: 1 I (12177986) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (12178708) wifi:Set ps type: 1 I (16132059) wifi:state: run -> init (ce00) I (16132061) wifi:pm stop, total sleep time: 3716134188 us / 3954093843 us I (16132062) wifi:new:<6,0>, old:<6,2>, ap:<255,255>, sta:<6,2>, prof:1 I (16132212) wifi:new:<6,2>, old:<6,0>, ap:<255,255>, sta:<6,2>, prof:1 I (16132214) wifi:state: init -> auth (b0) I (16132218) wifi:state: auth -> assoc (0) I (16132229) wifi:state: assoc -> run (10) I (16132239) wifi:connected with TEST-AP, aid = 1, channel 6, 40D, bssid = 18:a6:f7:ab:ca:66 I (16132240) wifi:security: WPA2-PSK, phy: bgn, rssi: -34 I (16132242) wifi:pm start, type: 1 I (16132263) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (16133209) wifi:Set ps type: 1 I (17025749) wifi:state: run -> init (ce00) I (17025752) wifi:pm stop, total sleep time: 840144164 us / 893506568 us I (17025753) wifi:new:<6,0>, old:<6,2>, ap:<255,255>, sta:<6,2>, prof:1 I (17025902) wifi:new:<6,2>, old:<6,0>, ap:<255,255>, sta:<6,2>, prof:1 I (17025904) wifi:state: init -> auth (b0) I (17025907) wifi:state: auth -> assoc (0) I (17025918) wifi:state: assoc -> run (10) I (17025926) wifi:connected with TEST-AP, aid = 1, channel 6, 40D, bssid = 18:a6:f7:ab:ca:66 I (17025927) wifi:security: WPA2-PSK, phy: bgn, rssi: -39 I (17025929) wifi:pm start, type: 1 I (17025957) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (17026708) wifi:Set ps type: 1 I (17027683) wifi:state: run -> init (ce00) I (17027684) wifi:pm stop, total sleep time: 975130 us / 1751554 us I (17027685) wifi:new:<6,0>, old:<6,2>, ap:<255,255>, sta:<6,2>, prof:1 I (17027835) wifi:new:<6,2>, old:<6,0>, ap:<255,255>, sta:<6,2>, prof:1 I (17027837) wifi:state: init -> auth (b0) I (17027840) wifi:state: auth -> assoc (0) I (17027851) wifi:state: assoc -> run (10) I (17027860) wifi:connected with TEST-AP, aid = 1, channel 6, 40D, bssid = 18:a6:f7:ab:ca:66 I (17027860) wifi:security: WPA2-PSK, phy: bgn, rssi: -31 I (17027863) wifi:pm start, type: 1 I (17027887) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (17028708) wifi:Set ps type: 1 I (18576161) wifi:state: run -> init (ce00) I (18576163) wifi:pm stop, total sleep time: 1454784004 us / 1548297351 us I (18576164) wifi:new:<6,0>, old:<6,2>, ap:<255,255>, sta:<6,2>, prof:1 I (18576314) wifi:new:<6,2>, old:<6,0>, ap:<255,255>, sta:<6,2>, prof:1 I (18576316) wifi:state: init -> auth (b0) I (18576319) wifi:state: auth -> assoc (0) I (18576354) wifi:state: assoc -> run (10) I (18576377) wifi:connected with TEST-AP, aid = 1, channel 6, 40D, bssid = 18:a6:f7:ab:ca:66 I (18576378) wifi:security: WPA2-PSK, phy: bgn, rssi: -32 I (18576380) wifi:pm start, type: 1 I (18576467) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (18577209) wifi:Set ps type: 1 I (20358550) wifi:state: run -> init (ce00) I (20358552) wifi:pm stop, total sleep time: 1676428099 us / 1782168687 us I (20358553) wifi:new:<6,0>, old:<6,2>, ap:<255,255>, sta:<6,2>, prof:1 I (20358703) wifi:new:<6,2>, old:<6,0>, ap:<255,255>, sta:<6,2>, prof:1 I (20358705) wifi:state: init -> auth (b0) I (20358708) wifi:state: auth -> assoc (0) I (20358719) wifi:state: assoc -> run (10) I (20358727) wifi:connected with TEST-AP, aid = 1, channel 6, 40D, bssid = 18:a6:f7:ab:ca:66 I (20358728) wifi:security: WPA2-PSK, phy: bgn, rssi: -39 I (20358730) wifi:pm start, type: 1 I (20358754) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (20359708) wifi:Set ps type: 1 I (20407499) wifi:state: run -> init (ce00) I (20407502) wifi:pm stop, total sleep time: 44970113 us / 48768394 us I (20407502) wifi:new:<6,0>, old:<6,2>, ap:<255,255>, sta:<6,2>, prof:1 I (20407652) wifi:new:<6,2>, old:<6,0>, ap:<255,255>, sta:<6,2>, prof:1 I (20407654) wifi:state: init -> auth (b0) I (20407657) wifi:state: auth -> assoc (0) I (20407668) wifi:state: assoc -> run (10) I (20407676) wifi:connected with TEST-AP, aid = 1, channel 6, 40D, bssid = 18:a6:f7:ab:ca:66 I (20407677) wifi:security: WPA2-PSK, phy: bgn, rssi: -32 I (20407679) wifi:pm start, type: 1 I (20407703) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (20408708) wifi:Set ps type: 1 I (27141199) wifi:state: run -> init (ce00) I (27141201) wifi:pm stop, total sleep time: 6331990914 us / 6733518724 us I (27141202) wifi:new:<6,0>, old:<6,2>, ap:<255,255>, sta:<6,2>, prof:1 I (27141352) wifi:new:<6,2>, old:<6,0>, ap:<255,255>, sta:<6,2>, prof:1 I (27141354) wifi:state: init -> auth (b0) I (27141357) wifi:state: auth -> assoc (0) I (27141368) wifi:state: assoc -> run (10) I (27141376) wifi:connected with TEST-AP, aid = 1, channel 6, 40D, bssid = 18:a6:f7:ab:ca:66 I (27141377) wifi:security: WPA2-PSK, phy: bgn, rssi: -39 I (27141379) wifi:pm start, type: 1 I (27141403) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (27142208) wifi:Set ps type: 1 I (62198561) wifi:state: run -> init (ce00) I (62198563) wifi:pm stop, total sleep time: 33048490823 us / 35057180990 us I (62198564) wifi:new:<6,0>, old:<6,2>, ap:<255,255>, sta:<6,2>, prof:1 I (62198714) wifi:new:<6,2>, old:<6,0>, ap:<255,255>, sta:<6,2>, prof:1 I (62198716) wifi:state: init -> auth (b0) I (62198719) wifi:state: auth -> assoc (0) I (62198730) wifi:state: assoc -> run (10) I (62198739) wifi:connected with TEST-AP, aid = 1, channel 6, 40D, bssid = 18:a6:f7:ab:ca:66 I (62198739) wifi:security: WPA2-PSK, phy: bgn, rssi: -37 I (62198742) wifi:pm start, type: 1 I (62198765) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (62199708) wifi:Set ps type: 1 I (62212053) wifi:state: run -> init (ce00) I (62212055) wifi:pm stop, total sleep time: 11259164 us / 13310613 us I (62212056) wifi:new:<6,0>, old:<6,2>, ap:<255,255>, sta:<6,2>, prof:1 I (62212206) wifi:new:<6,2>, old:<6,0>, ap:<255,255>, sta:<6,2>, prof:1 I (62212208) wifi:state: init -> auth (b0) I (62212211) wifi:state: auth -> assoc (0) I (62212224) wifi:state: assoc -> run (10) I (62212233) wifi:connected with TEST-AP, aid = 1, channel 6, 40D, bssid = 18:a6:f7:ab:ca:66 I (62212234) wifi:security: WPA2-PSK, phy: bgn, rssi: -38 I (62212237) wifi:pm start, type: 1 I (62212253) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (62213209) wifi:Set ps type: 1 I (62218893) wifi:state: run -> init (ce00) I (62218896) wifi:pm stop, total sleep time: 5147208 us / 6655829 us I (62218896) wifi:new:<6,0>, old:<6,2>, ap:<255,255>, sta:<6,2>, prof:1 I (62219046) wifi:new:<6,2>, old:<6,0>, ap:<255,255>, sta:<6,2>, prof:1 I (62219048) wifi:state: init -> auth (b0) I (62219051) wifi:state: auth -> assoc (0) I (62219062) wifi:state: assoc -> run (10) I (62219075) wifi:connected with TEST-AP, aid = 1, channel 6, 40D, bssid = 18:a6:f7:ab:ca:66 I (62219076) wifi:security: WPA2-PSK, phy: bgn, rssi: -40 I (62219078) wifi:pm start, type: 1 I (62219100) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (62219708) wifi:Set ps type: 1 I (62230943) wifi:state: run -> init (ce00) I (62230946) wifi:pm stop, total sleep time: 9631190 us / 11864185 us I (62230946) wifi:new:<6,0>, old:<6,2>, ap:<255,255>, sta:<6,2>, prof:1 I (62231096) wifi:new:<6,2>, old:<6,0>, ap:<255,255>, sta:<6,2>, prof:1 I (62231098) wifi:state: init -> auth (b0) I (62231101) wifi:state: auth -> assoc (0) I (62231112) wifi:state: assoc -> run (10) I (62231121) wifi:connected with TEST-AP, aid = 1, channel 6, 40D, bssid = 18:a6:f7:ab:ca:66 I (62231121) wifi:security: WPA2-PSK, phy: bgn, rssi: -37 I (62231124) wifi:pm start, type: 1 I (62231147) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (62231707) wifi:Set ps type: 1 I (62308341) wifi:state: run -> init (ce00) I (62308343) wifi:pm stop, total sleep time: 71955625 us / 77216118 us I (62308344) wifi:new:<6,0>, old:<6,2>, ap:<255,255>, sta:<6,2>, prof:1 I (62308493) wifi:new:<6,2>, old:<6,0>, ap:<255,255>, sta:<6,2>, prof:1 I (62308495) wifi:state: init -> auth (b0) I (62308504) wifi:state: auth -> assoc (0) I (62308519) wifi:state: assoc -> run (10) I (62308548) wifi:connected with TEST-AP, aid = 1, channel 6, 40D, bssid = 18:a6:f7:ab:ca:66 I (62308548) wifi:security: WPA2-PSK, phy: bgn, rssi: -38 I (62308551) wifi:pm start, type: 1 I (62308647) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (62309209) wifi:Set ps type: 1

AxelLin commented 4 years ago

My previous log uses WIFI_PS_MIN_MODEM. Also has similar disconnect issue with WIFI_PS_NONE. (see below log)

I (1733) wifi:set country: cc=US schan=1 nchan=11 policy=0 I (1826) wifi:mode : sta (f0:08:d1:79:8c:60) I (1950) wifi:new:<1,1>, old:<1,0>, ap:<255,255>, sta:<1,1>, prof:1 I (2483) wifi:state: init -> auth (b0) I (2488) wifi:state: auth -> assoc (0) I (2499) wifi:state: assoc -> run (10) I (2509) wifi:connected with TEST-AP, aid = 1, channel 1, 40U, bssid = 18:a6:f7:ab:ca:66 I (2510) wifi:security: WPA2-PSK, phy: bgn, rssi: -36 I (2511) wifi:pm start, type: 1 I (2527) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (3463) wifi:Set ps type: 0 I (1803977) wifi:state: run -> init (ce00) I (1803978) wifi:pm stop, total sleep time: 578233 us / 1801463917 us I (1803979) wifi:new:<1,0>, old:<1,1>, ap:<255,255>, sta:<1,1>, prof:1 I (1804127) wifi:new:<1,1>, old:<1,0>, ap:<255,255>, sta:<1,1>, prof:1 I (1804129) wifi:state: init -> auth (b0) I (1804155) wifi:state: auth -> assoc (0) I (1804168) wifi:state: assoc -> run (10) I (1804177) wifi:connected with TEST-AP, aid = 1, channel 1, 40U, bssid = 18:a6:f7:ab:ca:66 I (1804178) wifi:security: WPA2-PSK, phy: bgn, rssi: -39 I (1804180) wifi:pm start, type: 0 I (1804184) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (1804967) wifi:Set ps type: 0 I (1837167) wifi:state: run -> init (ce00) I (1837169) wifi:pm stop, total sleep time: 0 us / 32985686 us I (1837169) wifi:new:<1,0>, old:<1,1>, ap:<255,255>, sta:<1,1>, prof:1 I (1837305) wifi:new:<1,1>, old:<1,0>, ap:<255,255>, sta:<1,1>, prof:1 I (1837307) wifi:state: init -> auth (b0) I (1837312) wifi:state: auth -> assoc (0) I (1837325) wifi:state: assoc -> run (10) I (1837334) wifi:connected with TEST-AP, aid = 1, channel 1, 40U, bssid = 18:a6:f7:ab:ca:66 I (1837335) wifi:security: WPA2-PSK, phy: bgn, rssi: -40 I (1837337) wifi:pm start, type: 0 I (1837383) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (1837966) wifi:Set ps type: 0

sim-lan commented 4 years ago

I have the similar issue on a different IDF

Environment

Problem Description

In the environment of our customer, the ESP disconnects continuously from AP with the WIFI_REASON_ASSOC_LEAVE reason. There is no problem with mine or any other tested environments yet. Our customer have many APs with the same SSIDs active in the system. Another problem is that the ESP does not find all visible networks (the strongest RSSI with the same SSID will not be found).

Expected Behavior

WiFi should stay connected constantly.

Acutal Behavior

WiFi disconnects from AP continuously.

Steps to reproduce

Hard to say. Maybe there is a problem with multiple APs with the same SSIDs which should be connected.

Code to reproduce this issue

I cannot provide my application code, but data from the logging of the wifi module.

Debug Logs

... WiFi is connected... and disconnects...

I (410048) wifi:state: run -> init (ce00)
D (410049) wifi:connect status 5 -> 6
D (410050) wifi:stop beacon/connect timer, send diassoc(8)
D (410052) wifi:sta leave
I (410053) wifi:pm stop, total sleep time: 17275222 us / 28990895 us

D (410065) wifi:stop CSA timer
D (410065) wifi:remove c0:ea:e4:e5:a6:8c from rc list
I (410067) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
D (410078) wifi:filter: set rx policy=8
D (410079) wifi:Send disconnect event, reason=8, AP number=0
D (410092) wlan: WIFI_EVENT_STA_DISCONNECTED(reason=8)
D (410094) wifi:Start wifi connect
D (410095) wifi:connect status 6 -> 0
D (410095) wifi:connect chan=0
D (410106) wifi:first chan=1
D (410107) wifi:connect status 0 -> 1
D (410108) wifi:filter: set rx policy=3
D (410110) wifi:clear scan ap list
D (410110) wifi:start scan: type=0x50f, priority=2, cb=0x4017b814, arg=0x0, ss_state=0x1, time=408334066, index=0
0x4017b814: cnx_start_handoff_cb at ??:?

D (410123) wifi:perform scan: ss_state=0x9, chan<1,0>, dur<0,120>
I (410136) wlan: Sending WLAN_CONNECTING(error=ESP_OK)
D (410140) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (410142) wifi:profile match: ss_state=0x7
D (410144) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (410156) wifi:profile match: ss_state=0x7
D (410375) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (410377) wifi:find first mathched ssid, scan done
D (410378) wifi:filter: set rx policy=4
D (410379) wifi:first chan=1
D (410390) wifi:handoff_cb: status=0
D (410391) wifi:ap found, mac=c0:ea:e4:e5:a6:8c
D (410392) wifi:new_bss=0x3ffca568, cur_bss=0x0, new_chan=<1,0>, cur_chan=1
D (410404) wifi:filter: set rx policy=5
I (410405) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
D (410406) wifi:connect_op: status=0, auth=5, cipher=3
D (410418) wifi:auth mode is not none
D (410419) wifi:connect_bss: auth=1, reconnect=0
I (410420) wifi:state: init -> auth (b0)
D (410422) wifi:start 1s AUTH timer
D (410434) wifi:clear scan ap list
I (410409) ble: Sending BLE_WRITE(status=ESP_OK, id=0x200B)
D (410440) wifi:recv auth: seq=2, status=0
I (410441) wifi:state: auth -> assoc (0)
D (410443) wifi:restart connect 1s timer for assoc
D (410455) wifi:recv auth: seq=2, status=0
D (410456) wifi:not auth state, ignore
D (410457) wifi:recv auth: seq=2, status=0
D (410458) wifi:not auth state, ignore
D (410469) wifi:recv assoc: type=0x10
D (410471) wifi:filter: set rx policy=6
I (410472) wifi:state: assoc -> run (10)
D (410473) wifi:start 10s connect timer for 4 way handshake
I (410507) wifi:connected with AP-WLAN-Partner, aid = 1, channel 1, BW20, bssid = c0:ea:e4:e5:a6:8c
I (410509) wifi:security: WPA2-PSK, phy: bgn, rssi: -84
D (410510) wifi:remove all except c0:ea:e4:e5:a6:8c from rc list
D (410522) wifi:clear blacklist
D (410526) wifi:filter: set rx policy=7
I (410527) wifi:pm start, type: 1

D (410528) wifi:Send sta connected event
D (410540) wifi:connect status 1 -> 5
D (410540) wifi:obss scan is disabled
D (410541) wifi:start obss scan: obss scan is stopped
D (410542) wlan: WIFI_EVENT_STA_CONNECTED()
I (411070) wifi:AP's beacon interval = 1024000 us, DTIM period = 1
D (411073) wifi:set max rate: from <rate=130, phy=3, sig=0> to <rate=144, phy=3 sig=0>
D (411075) wifi:sig_b=0, sig_g=0, sig_n=0, max_b=22, max_g=108, max_n=144
D (411086) wifi:update trc
D (411516) wifi:obss scan is disabled
D (411517) wifi:start obss scan: obss scan is stopped
D (412524) wifi:obss scan is disabled
D (412525) wifi:start obss scan: obss scan is stopped
I (412659) ble: Sending BLE_NOTIFY(status=ESP_OK, id=0x2001, length=4, data)
D (413533) wifi:obss scan is disabled
D (413534) wifi:start obss scan: obss scan is stopped
D (414530) wifi:recv disassoc: reason=2
I (414532) wifi:state: run -> init (2a0)
D (414533) wifi:recv deauth/disassoc, stop beacon/connect timer
D (414534) wifi:connect status 5 -> 4
D (414545) wifi:sta leave
I (414546) wifi:pm stop, total sleep time: 1530619 us / 4017954 us

D (414547) wifi:stop CSA timer
D (414548) wifi:remove c0:ea:e4:e5:a6:8c from rc list
I (414560) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
D (414561) wifi:filter: set rx policy=8
D (414562) wifi:Send disconnect event, reason=2, AP number=0
D (414574) wlan: WIFI_EVENT_STA_DISCONNECTED(reason=2)
D (414575) wifi:Start wifi connect
D (414576) wifi:connect status 4 -> 0
D (414587) wifi:connect chan=0
D (414588) wifi:first chan=1
D (414589) wifi:connect status 0 -> 1
D (414589) wifi:filter: set rx policy=3
D (414601) wifi:clear scan ap list
D (414601) wifi:start scan: type=0x50f, priority=2, cb=0x4017b814, arg=0x0, ss_state=0x1, time=412825632, index=0
0x4017b814: cnx_start_handoff_cb at ??:?

D (414614) wifi:perform scan: ss_state=0x9, chan<1,0>, dur<0,120>
D (414620) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (414623) wifi:profile match: ss_state=0x7
D (414625) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (414626) wifi:profile match: ss_state=0x7
D (414702) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (414703) wifi:set max rate: from <rate=130, phy=3, sig=0> to <rate=144, phy=3 sig=0>
D (414705) wifi:sig_b=0, sig_g=0, sig_n=0, max_b=22, max_g=108, max_n=144
D (414717) wifi:profile match: ss_state=0x7
D (414856) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (414858) wifi:find first mathched ssid, scan done
D (414859) wifi:filter: set rx policy=4
D (414859) wifi:first chan=1
D (414870) wifi:handoff_cb: status=0
D (414871) wifi:ap found, mac=c0:ea:e4:e5:8b:32
D (414872) wifi:new_bss=0x3ffca568, cur_bss=0x0, new_chan=<1,0>, cur_chan=1
D (414884) wifi:filter: set rx policy=5
I (414885) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
D (414886) wifi:connect_op: status=0, auth=5, cipher=3
D (414898) wifi:auth mode is not none
D (414899) wifi:connect_bss: auth=1, reconnect=0
I (414900) wifi:state: init -> auth (b0)
D (414912) wifi:start 1s AUTH timer
D (414914) wifi:clear scan ap list
D (414918) wifi:recv auth: seq=2, status=0
I (414919) wifi:state: auth -> assoc (0)
D (414921) wifi:restart connect 1s timer for assoc
D (414927) wifi:recv assoc: type=0x10
D (414928) wifi:filter: set rx policy=6
I (414929) wifi:state: assoc -> run (10)
D (414941) wifi:start 10s connect timer for 4 way handshake
D (415726) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

I (415958) wifi:connected with AP-WLAN-Partner, aid = 1, channel 1, BW20, bssid = c0:ea:e4:e5:8b:32
I (415961) wifi:security: WPA2-PSK, phy: bgn, rssi: -84
D (415973) wifi:remove all except c0:ea:e4:e5:8b:32 from rc list
D (415974) wifi:clear blacklist
D (415978) wifi:filter: set rx policy=7
I (415979) wifi:pm start, type: 1

D (415980) wifi:Send sta connected event
D (415992) wifi:connect status 1 -> 5
D (415992) wifi:obss scan is disabled
D (415993) wifi:start obss scan: obss scan is stopped
D (415994) wlan: WIFI_EVENT_STA_CONNECTED()
I (416750) wifi:AP's beacon interval = 1024000 us, DTIM period = 1
D (420868) wlan: IP_EVENT_STA_GOT_IP(172.17.100.92)
I (420870) wlan: Sending WLAN_CONNECTED_INET(error=ESP_OK)
I (420871) wlan: Sending WLAN_TIME_SYNC(error=ESP_OK)
I (420883) tcpip_adapter: sta ip: 172.17.100.92, mask: 255.255.255.0, gw: 172.17.100.1

... WiFi is connected and disconnects again...

I (490607) wifi:state: run -> init (ce00)
D (490608) wifi:connect status 5 -> 6
D (490609) wifi:stop beacon/connect timer, send diassoc(8)
D (490611) wifi:sta leave
I (490612) wifi:pm stop, total sleep time: 39265799 us / 74631739 us

D (490624) wifi:stop CSA timer
D (490624) wifi:remove c0:ea:e4:e5:8b:32 from rc list
I (490626) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
D (490637) wifi:filter: set rx policy=8
D (490638) wifi:Send disconnect event, reason=8, AP number=0
D (490651) wlan: WIFI_EVENT_STA_DISCONNECTED(reason=8)
D (490653) wifi:Start wifi connect
D (490654) wifi:connect status 6 -> 0
D (490656) wifi:connect chan=0
D (490667) wifi:first chan=1
D (490668) wifi:connect status 0 -> 1
D (490669) wifi:filter: set rx policy=3
D (490669) wifi:clear scan ap list
D (490670) wifi:start scan: type=0x50f, priority=2, cb=0x4017b814, arg=0x0, ss_state=0x1, time=488913786, index=0
0x4017b814: cnx_start_handoff_cb at ??:?

D (490682) wifi:perform scan: ss_state=0x9, chan<1,0>, dur<0,120>
I (490660) ble: Sending BLE_NOTIFY(status=ESP_OK, id=0x2001, length=4, data)
I (490699) wlan: Sending WLAN_CONNECTING(error=ESP_OK)
D (490700) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (490713) wifi:profile match: ss_state=0x7
D (490715) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (490717) wifi:profile match: ss_state=0x7
D (490935) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (490937) wifi:find first mathched ssid, scan done
D (490938) wifi:filter: set rx policy=4
D (490939) wifi:first chan=1
D (490950) wifi:handoff_cb: status=0
D (490951) wifi:ap found, mac=c0:ea:e4:e5:8b:32
D (490952) wifi:new_bss=0x3ffca860, cur_bss=0x0, new_chan=<1,0>, cur_chan=1
D (490963) wifi:filter: set rx policy=5
I (490965) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
D (490966) wifi:connect_op: status=0, auth=5, cipher=3
D (490977) wifi:auth mode is not none
D (490979) wifi:connect_bss: auth=1, reconnect=0
I (490980) wifi:state: init -> auth (b0)
D (490992) wifi:start 1s AUTH timer
D (490993) wifi:clear scan ap list
D (490998) wifi:recv auth: seq=2, status=0
I (491010) wifi:state: auth -> assoc (0)
D (491011) wifi:restart connect 1s timer for assoc
D (491018) wifi:recv assoc: type=0x10
D (491019) wifi:filter: set rx policy=6
I (491020) wifi:state: assoc -> run (10)
D (491022) wifi:start 10s connect timer for 4 way handshake
I (491057) wifi:connected with AP-WLAN-Partner, aid = 1, channel 1, BW20, bssid = c0:ea:e4:e5:8b:32
I (491059) wifi:security: WPA2-PSK, phy: bgn, rssi: -86
D (491060) wifi:remove all except c0:ea:e4:e5:8b:32 from rc list
D (491072) wifi:clear blacklist
D (491076) wifi:filter: set rx policy=7
I (491077) wifi:pm start, type: 1

D (491078) wifi:Send sta connected event
D (491090) wifi:connect status 1 -> 5
D (491091) wifi:obss scan is disabled
D (491091) wifi:start obss scan: obss scan is stopped
D (491092) wlan: WIFI_EVENT_STA_CONNECTED()
D (491168) wifi:obss scan is disabled
D (491169) wifi:start obss scan: obss scan is stopped
I (491629) wifi:AP's beacon interval = 1024000 us, DTIM period = 1
D (491632) wifi:set max rate: from <rate=130, phy=3, sig=0> to <rate=144, phy=3 sig=0>
D (491635) wifi:sig_b=0, sig_g=0, sig_n=0, max_b=22, max_g=108, max_n=144
D (491646) wifi:update trc
D (496368) wlan: IP_EVENT_STA_GOT_IP(172.17.100.92)
I (496370) wlan: Sending WLAN_CONNECTED_INET(error=ESP_OK)
I (496371) wlan: Sending WLAN_TIME_SYNC(error=ESP_OK)
I (496383) tcpip_adapter: sta ip: 172.17.100.92, mask: 255.255.255.0, gw: 172.17.100.1
AxelLin commented 4 years ago

My test environment only has one AP named TEST-AP, It's not related to multiple APs with the same SSIDs in my case.

liuzfesp commented 4 years ago

Hi @AxelLin @DonSimonus, the WiFi is disconnected because the AP has reset its TSF timer, in other words, the AP may has problem about its TSF timer.

The disconnect reason code (0xce00) is: WIFI_REASON_AP_TSF_RESET, it indicates that the TSF value in AP's beacon has been reset. For example, the TSF value in last beacon of AP is 0x123456789 (last_tsf_value), the TSF value in new beacon of AP is 0x12345678 (new_tsf_value), if new_tsf_value is less than last_tsf_value, ESP32 STA will disconnect the WiFi and raise reason code WIFI_REASON_AP_TSF_RESET.

If the AP has TSF timer issue, I guess the issue should be stable and easy to be reproduced. Suggest to:

AxelLin commented 4 years ago

Hi @AxelLin @DonSimonus, the WiFi is disconnected because the AP has reset its TSF timer, in other words, the AP may has problem about its TSF timer.

The disconnect reason code (0xce00) is: WIFI_REASON_AP_TSF_RESET, it indicates that the TSF value in AP's beacon has been reset.

Hi @liuzfesp ,

I don't get it. No idea which part of the log shows 0xce00 as you mentioned? In my original report, I mentioned disconnected->reason, it's 8 (WIFI_REASON_ASSOC_LEAVE).

zhangyanjiaoesp commented 4 years ago

Hi @AxelLin @DonSimonus, the WiFi is disconnected because the AP has reset its TSF timer, in other words, the AP may has problem about its TSF timer. The disconnect reason code (0xce00) is: WIFI_REASON_AP_TSF_RESET, it indicates that the TSF value in AP's beacon has been reset.

Hi @liuzfesp ,

I don't get it. No idea which part of the log shows 0xce00 as you mentioned? In my original report, I mentioned disconnected->reason, it's 8 (WIFI_REASON_ASSOC_LEAVE).

Hi @AxelLin, It's I (253848) wifi:state: run -> init (ce00). Can you provide a capture of your issues?

AxelLin commented 4 years ago

Hi @liuzfesp , I don't get it. No idea which part of the log shows 0xce00 as you mentioned? In my original report, I mentioned disconnected->reason, it's 8 (WIFI_REASON_ASSOC_LEAVE).

Hi @AxelLin, It's I (253848) wifi:state: run -> init (ce00). Can you provide a capture of your issues?

Hi @zhangyanjiaoesp When I got WIFI_EVENT_STA_DISCONNECTED, I use below code to get disconnected reason. wifi_event_sta_disconnected_t disconnected = (wifi_event_sta_disconnected_t ) event_data; ESP_LOGI(TAG,"Disconnect reason: %d", disconnected->reason);

So why I got 8 WIFI_REASON_ASSOC_LEAVE rather than 206 WIFI_REASON_AP_TSF_RESET.

This is probably off-topic, but I hope disconnected->reason shows correct disconnect reason.

zhangyanjiaoesp commented 4 years ago

Hi @liuzfesp , I don't get it. No idea which part of the log shows 0xce00 as you mentioned? In my original report, I mentioned disconnected->reason, it's 8 (WIFI_REASON_ASSOC_LEAVE).

Hi @AxelLin, It's I (253848) wifi:state: run -> init (ce00). Can you provide a capture of your issues?

Hi @zhangyanjiaoesp When I got WIFI_EVENT_STA_DISCONNECTED, I use below code to get disconnected reason. wifi_event_sta_disconnected_t disconnected = (wifi_event_sta_disconnected_t ) event_data; ESP_LOGI(TAG,"Disconnect reason: %d", disconnected->reason);

So why I got 8 WIFI_REASON_ASSOC_LEAVE rather than 206 WIFI_REASON_AP_TSF_RESET.

This is probably off-topic, but I hope disconnected->reason shows correct disconnect reason.

The reason code WIFI_REASON_AP_TSF_RESET(206) is defined by ourself, it's not the standard reason in the protocol, when we want to send deauth/disassoc packets, we need to add the reason code IE , so we change the reason to WIFI_REASON_ASSOC_LEAVE(8), thus the receiver can parse it correctly.

image image

gecko242 commented 4 years ago

Huh, this is all looking very familiar! I am experiencing very similar problems. Previously, I have had no issues connecting to wifi, and staying connected. Unfortunately I cannot put an exact date to when it started, but recently I have been experiencing similar dropouts.

Typically these occur 15s - 1 minute after connecting.

Module or chip used: ESP32-WROOM-32U 16MB IDF version: v4.3-dev-472-gcf056a7d0 Build System: idf.py Operating System: Windows Power Supply: Custom PCB

I (38292) wifi:state: run -> init (ce00)
I (38292) wifi:pm stop, total sleep time: 11798559 us / 14399660 us

I (38292) wifi:new:<11,0>, old:<11,0>, ap:<11,2>, sta:<11,0>, prof:1
I (06:36:23.724) SafeGuard.network: Disconnect Reason: 8

I have recently been changing some WiFI stuff, but nothing directly related to the connection configuration.

Whilst this could well be due to changes in our router configuration (I dont get involved in the company IT to that level!), its interesting that these have cropped up at the same time!

sim-lan commented 4 years ago

Hi @AxelLin @DonSimonus, the WiFi is disconnected because the AP has reset its TSF timer, in other words, the AP may has problem about its TSF timer.

The disconnect reason code (0xce00) is: WIFI_REASON_AP_TSF_RESET, it indicates that the TSF value in AP's beacon has been reset. For example, the TSF value in last beacon of AP is 0x123456789 (last_tsf_value), the TSF value in new beacon of AP is 0x12345678 (new_tsf_value), if new_tsf_value is less than last_tsf_value, ESP32 STA will disconnect the WiFi and raise reason code WIFI_REASON_AP_TSF_RESET.

If the AP has TSF timer issue, I guess the issue should be stable and easy to be reproduced. Suggest to:

  • Change to a different AP and do a test
  • Still use the same AP and capture the WiFi packets and we will double confirm the AP's TSF issue via packets

Hi @liuzfesp Unfortunately I can't take care of the problem this week because I'm on vacation.

Our customer has already tested it with a different AP (e.g. by a hotspot on a smartphone, AP at home etc.) and there it worked without problems. It sounds like a problem with the APs at the customer's company environment.

Is this a known behavior of APs with this TSF reset, or what is the trigger for that? How is that meant by "capture the WiFi packets"? Extend the debug log on the ESP or record the packets via a sniffer on the AP?

negativekelvin commented 4 years ago

we need to add the reason code IE , so we change the reason to WIFI_REASON_ASSOC_LEAVE(8), thus the receiver can parse it correctly.

@zhangyanjiaoesp ok to send a valid reason code to the AP but why change it within the callback data?

zhangyanjiaoesp commented 4 years ago

we need to add the reason code IE , so we change the reason to WIFI_REASON_ASSOC_LEAVE(8), thus the receiver can parse it correctly.

@zhangyanjiaoesp ok to send a valid reason code to the AP but why change it within the callback data?

Maybe we will optimize it in the future.

zhangyanjiaoesp commented 4 years ago

Hi @AxelLin @DonSimonus, the WiFi is disconnected because the AP has reset its TSF timer, in other words, the AP may has problem about its TSF timer. The disconnect reason code (0xce00) is: WIFI_REASON_AP_TSF_RESET, it indicates that the TSF value in AP's beacon has been reset. For example, the TSF value in last beacon of AP is 0x123456789 (last_tsf_value), the TSF value in new beacon of AP is 0x12345678 (new_tsf_value), if new_tsf_value is less than last_tsf_value, ESP32 STA will disconnect the WiFi and raise reason code WIFI_REASON_AP_TSF_RESET. If the AP has TSF timer issue, I guess the issue should be stable and easy to be reproduced. Suggest to:

  • Change to a different AP and do a test
  • Still use the same AP and capture the WiFi packets and we will double confirm the AP's TSF issue via packets

Hi @liuzfesp Unfortunately I can't take care of the problem this week because I'm on vacation.

Our customer has already tested it with a different AP (e.g. by a hotspot on a smartphone, AP at home etc.) and there it worked without problems. It sounds like a problem with the APs at the customer's company environment.

Is this a known behavior of APs with this TSF reset, or what is the trigger for that?

If user reset the router, the TSF timer will be reset.

How is that meant by "capture the WiFi packets"? Extend the debug log on the ESP or record the packets via a sniffer on the AP?

You can use an software (Omnipeek or Wireshark) to capture the wireless packets.

sim-lan commented 4 years ago

Hi @AxelLin @DonSimonus, the WiFi is disconnected because the AP has reset its TSF timer, in other words, the AP may has problem about its TSF timer. The disconnect reason code (0xce00) is: WIFI_REASON_AP_TSF_RESET, it indicates that the TSF value in AP's beacon has been reset. For example, the TSF value in last beacon of AP is 0x123456789 (last_tsf_value), the TSF value in new beacon of AP is 0x12345678 (new_tsf_value), if new_tsf_value is less than last_tsf_value, ESP32 STA will disconnect the WiFi and raise reason code WIFI_REASON_AP_TSF_RESET. If the AP has TSF timer issue, I guess the issue should be stable and easy to be reproduced. Suggest to:

  • Change to a different AP and do a test
  • Still use the same AP and capture the WiFi packets and we will double confirm the AP's TSF issue via packets

Hi @liuzfesp Unfortunately I can't take care of the problem this week because I'm on vacation. Our customer has already tested it with a different AP (e.g. by a hotspot on a smartphone, AP at home etc.) and there it worked without problems. It sounds like a problem with the APs at the customer's company environment. Is this a known behavior of APs with this TSF reset, or what is the trigger for that?

If user reset the router, the TSF timer will be reset.

The user do not reset the router(s) manually (I was there during the tests). Are there other influences that forces the AP to reset by itself (or just the TSF timer)?

How is that meant by "capture the WiFi packets"? Extend the debug log on the ESP or record the packets via a sniffer on the AP?

You can use an software (Omnipeek or Wireshark) to capture the wireless packets.

So do you recommend sniffing (e.g. with Wireshark) directly on the router via LAN connection? Wouldn't it be a possibility to enable the IP debugging/logging (#define IP_DEBUG LWIP_DBG_OFN) on the ESP in order to visualize the packets?

negativekelvin commented 4 years ago

@DonSimonus you need to sniff the raw packets directly off the air using a WiFi adapter that supports promiscuous. There are a few projects that use esp32 as a sniffer including https://github.com/espressif/esp-idf/blob/625bd5eb1806809ff3cc010ee20d1f750aa778a1/examples/wifi/simple_sniffer/README.md

negativekelvin commented 4 years ago

https://github.com/espressif/esp32-wifi-lib/commit/435347a24cec805f81319d3ac6d2a2f17da57bd5

sim-lan commented 4 years ago

@DonSimonus you need to sniff the raw packets directly off the air using a WiFi adapter that supports promiscuous. There are a few projects that use esp32 as a sniffer including https://github.com/espressif/esp-idf/blob/625bd5eb1806809ff3cc010ee20d1f750aa778a1/examples/wifi/simple_sniffer/README.md

@negativekelvin Thanks for your inputs. Do you know if it's a "normal" behaviour of WiFi clients to disconnect from APs if the TFS timer resets? Are there other influences that forces the AP to reset by itself (or just the TSF timer)?

negativekelvin commented 4 years ago

Tsf timer should not reset, it may be ok to disconnect if it actually reset to zero. I don't think we know whether it did or if an out of order timestamp was received due to mesh/repeater properties and the check was too strict.

AxelLin commented 4 years ago

Hi @negativekelvin

Is it ok to capture the log with wireshark? If yes, what is the recommend filter setting for only showing TSF related packets?

sim-lan commented 4 years ago

Hi @negativekelvin

Is it ok to capture the log with wireshark? If yes, what is the recommend filter setting for only showing TSF related packets?

I have the same question. Since in my case its a network in a company, there is a lot of traffic. Does it make sense to filter for the MAC address of the Espressif module or are there other "characteristics" of the regarding packages?

AxelLin commented 3 years ago

espressif/esp32-wifi-lib@435347a

I still observed the same symptom with esp32-wifi-lib update. So it's not clear to me if it's AP malfunction or something wong in ESP32 side. Is it possible to show some debug info regarding received tsf timer value if enable verbose or debug log?

sim-lan commented 3 years ago

espressif/esp32-wifi-lib@435347a

Hi @negativekelvin Because I work on the 4.0 branch (v4.0.1-412-g820621687), I cannot try out the changes in my project without adapting the IDF version, which would result in further necessary changes in my project. Is it therefore possible to implement the adaptation on the 4.0 branch as well?

zhangyanjiaoesp commented 3 years ago

@DonSimonus

The changes has been backported to v4.0, please wait for the latest release.

zhangyanjiaoesp commented 3 years ago

Hi @negativekelvin

Is it ok to capture the log with wireshark? If yes, what is the recommend filter setting for only showing TSF related packets?

You can capture wifi packets with wireshark, you can set the STA and AP's MAC address as the filter.

sim-lan commented 3 years ago

@DonSimonus

The changes has been backported to v4.0, please wait for the latest release.

@zhangyanjiaoesp Many thanks. When do you think this will be integrated into the IDF and the release is available?

zhangyanjiaoesp commented 3 years ago

@DonSimonus

The v4.0.2 ( e5f754b) has been released, and the related change is db733d7321d35c21c6e0d055c939c0568b325cd9

mbratch commented 3 years ago

I'm using ESP-IDF v4.3 and I get a wifi disconnect once or twice per day. I have 5 devices running the same code and they all get this disconnect at exactly the same time. They each take 40 seconds of retries and finally reconnect again. These are the messages that roll out for 40 seconds (the BD-PTB message is my log message when the disconnect event occurs):

I (78298) wifi:new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1
I (78308) wifi:state: init -> auth (b0)
I (78308) wifi:state: auth -> init (600)
I (78308) wifi:new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1
W (78308) BD-PTB: wifiEvent: wifi disconnect occurred; attempting reconnect
W (80368) BD-PTB: wifiEvent: wifi disconnect occurred; attempting reconnect

My reason code is different than reported above. I'm seeing an "init (600)" which I assume is a reason code 6: WIFI_REASON_NOT_AUTHED according to the header file. The devices all authenticate just fine. I'm not sure why this disconnect would occur.

AxelLin commented 3 years ago

My reason code is different than reported above. I'm seeing an "init (600)" which I assume is a reason code 6: WIFI_REASON_NOT_AUTHED according to the header file. The devices all authenticate just fine. I'm not sure why this disconnect would occur.

Hi @mbratch Please create a new issue to make it easier to trace the issue.

mbratch commented 3 years ago

My reason code is different than reported above. I'm seeing an "init (600)" which I assume is a reason code 6: WIFI_REASON_NOT_AUTHED according to the header file. The devices all authenticate just fine. I'm not sure why this disconnect would occur.

Hi @mbratch Please create a new issue to make it easier to trace the issue.

Thank you. I have submitted issue #7286. I did some further debug and discovered the initial failure is due to MIC and then subsequent failures are authentication failures.