Wifi disconnects and is unable to reconnect with WIFI_REASON_MIC_FAILURE code (IDFGH-5142)

robertoimai commented 3 years ago

Environment

Module or chip used: ESP32-WROVER-E
IDF version (run git describe --tags to find it): v4.2
Build System: idf.py
Compiler version (run xtensa-esp32-elf-gcc --version to find it): xtensa-esp32-elf-gcc (crosstool-NG esp-2020r3) 8.4.0
Operating System: Windows
(Windows only) environment type: VSCode.
Using an IDE?: VSCode]
Power Supply: external 3.3V

Problem Description

Module is disconnecting from wifi with reason code 14 (WIFI_REASON_MIC_FAILURE). Any attempt to reconnect will also fail. You can see from the log that the failure did take a long time to show up. About 75hrs. I saw a reference similar here: https://github.com/espressif/esp-idf/issues/5023 But it led to stale. My router is a TPLink AC1750

Debug Logs

I (184827287) wifi:state: run -> init (6c0) I (184827297) wifi:pm stop, total sleep time: 101950385411 us / 120855147958 us

I (184827297) wifi:new:<2,0>, old:<2,0>, ap:<255,255>, sta:<2,0>, prof:1 [0;32mI (184827307) SOUND: Send sound queue: 146-1[0m [0;32mI (184827347) WIFI: Disconnected from wifi:6[0m [0;32mI (184827347) SOUND: Playing: /spiffs/wifi_disconnected.mp3[0m [0;32mI (184827347) WIFI: connection_retry: 1[0m [0;32mI (184827397) WIFI: MQTT task stopping...[0m I (184828477) wifi:new:<2,0>, old:<2,0>, ap:<255,255>, sta:<2,0>, prof:1 I (184828477) wifi:state: init -> auth (b0) I (184828487) wifi:state: auth -> assoc (0) I (184828497) wifi:state: assoc -> run (10) I (184828497) wifi:state: run -> init (ea0) I (184828497) wifi:new:<2,0>, old:<2,0>, ap:<255,255>, sta:<2,0>, prof:1 I (184828497) wifi:new:<2,0>, old:<2,0>, ap:<255,255>, sta:<2,0>, prof:1 [0;32mI (184828517) WIFI: Disconnected from wifi:14[0m [0;32mI (184828517) WIFI: connection_retry: 2[0m [0;32mI (184828787) SOUND: Finished: /spiffs/wifi_disconnected.mp3[0m [0;32mI (184831577) WIFI: Disconnected from wifi:205[0m [0;32mI (184831577) WIFI: connection_retry: 3[0m I (184832697) wifi:new:<2,0>, old:<2,0>, ap:<255,255>, sta:<2,0>, prof:1 I (184832697) wifi:state: init -> auth (b0) I (184832707) wifi:state: auth -> assoc (0) I (184832707) wifi:state: assoc -> run (10) I (184832717) wifi:state: run -> init (ea0) I (184832717) wifi:new:<2,0>, old:<2,0>, ap:<255,255>, sta:<2,0>, prof:1 I (184832717) wifi:new:<2,0>, old:<2,0>, ap:<255,255>, sta:<2,0>, prof:1 [0;32mI (184832727) WIFI: Disconnected from wifi:14[0m [0;32mI (184832727) WIFI: connection_retry: 4[0m [0;32mI (184835787) WIFI: Disconnected from wifi:205[0m [0;32mI (184835787) WIFI: connection_retry: 5[0m I (184836907) wifi:new:<2,0>, old:<2,0>, ap:<255,255>, sta:<2,0>, prof:1 I (184836907) wifi:state: init -> auth (b0) I (184836907) wifi:state: auth -> assoc (0) I (184836917) wifi:state: assoc -> run (10) I (184836917) wifi:state: run -> init (ea0) I (184836917) wifi:new:<2,0>, old:<2,0>, ap:<255,255>, sta:<2,0>, prof:1 I (184836927) wifi:new:<2,0>, old:<2,0>, ap:<255,255>, sta:<2,0>, prof:1 [0;32mI (184836937) WIFI: Disconnected from wifi:14[0m [0;32mI (184836937) WIFI: connection_retry: 6[0m [0;32mI (184839997) WIFI: Disconnected from wifi:205[0m [0;32mI (184839997) WIFI: connection_retry: 7[0m I (184841117) wifi:new:<2,0>, old:<2,0>, ap:<255,255>, sta:<2,0>, prof:1 I (184841117) wifi:state: init -> auth (b0) I (184841127) wifi:state: auth -> assoc (0) I (184841147) wifi:state: assoc -> run (10) I (184841147) wifi:state: run -> init (ea0) I (184841147) wifi:new:<2,0>, old:<2,0>, ap:<255,255>, sta:<2,0>, prof:1 I (184841147) wifi:new:<2,0>, old:<2,0>, ap:<255,255>, sta:<2,0>, prof:1 [0;32mI (184841157) WIFI: Disconnected from wifi:14[0m [0;32mI (184841157) WIFI: connection_retry: 8[0m [0;32mI (184844217) WIFI: Disconnected from wifi:205[0m [0;32mI (184844217) WIFI: connection_retry: 9[0m I (184845337) wifi:new:<2,0>, old:<2,0>, ap:<255,255>, sta:<2,0>, prof:1 I (184845337) wifi:state: init -> auth (b0) I (184845347) wifi:state: auth -> assoc (0) I (184845357) wifi:state: assoc -> run (10) I (184845357) wifi:state: run -> init (ea0) I (184845357) wifi:new:<2,0>, old:<2,0>, ap:<255,255>, sta:<2,0>, prof:1 I (184845367) wifi:new:<2,0>, old:<2,0>, ap:<255,255>, sta:<2,0>, prof:1 [0;32mI (184845377) WIFI: Disconnected from wifi:14[0m [0;32mI (184845377) WIFI: connection_retry: 10[0m [0;32mI (184848437) WIFI: Disconnected from wifi:205[0m [0;32mI (184848437) WIFI: connection_retry: 11[0m [0;32mI (184848437) WIFI: Scanning for wifi networks...[0m [0;32mI (184850557) WIFI: Scan Done[0m [0;32mI (184850557) WIFI: RAM left 4015652[0m [0;32mI (184850557) WIFI: provisioned: 1[0m [0;32mI (184850557) WIFI: SSID 0:Azena Guest[0m [0;32mI (184850567) WIFI: SSID 1:Azena F[0m [0;32mI (184850567) WIFI: Attempting to connect to wifi Azena F[0m [0;32mI (184850577) WIFI: SSID 2:DIRECT-C5-HP OfficeJet Pro 8710[0m [0;32mI (184850577) WIFI: SSID 3:PFF-2.4G[0m [0;32mI (184850587) WIFI: SSID 4:BridgeWC[0m [0;32mI (184850587) WIFI: SSID 5:GORDON REESE DESIGN BUILD[0m [0;32mI (184850587) WIFI: SSID 6:GORDON REESE guest[0m [0;32mI (184850597) WIFI: SSID 7:PFF-2.4G_RPT[0m [0;32mI (184850597) WIFI: SSID 8:DIRECT-ba-HP M277 LaserJet[0m [0;32mI (184850617) WIFI: SSID 9:PAD5[0m [0;32mI (184850617) WIFI: SSID 10:DIRECT-3e-HP M118 LaserJet[0m [0;32mI (184850617) WIFI: SSID 11:Pocklingtonlaw[0m [0;32mI (184850627) WIFI: SSID 12:evanjuliet-2.4[0m [0;32mI (184850627) WIFI: SSID 13:VAAK LLP[0m [0;32mI (184850627) WIFI: SSID 14:DIRECT-64-HP OfficeJet Pro 8710[0m [0;32mI (184850637) WIFI: SSID 15:Cappo-2.4[0m [0;32mI (184850637) WIFI: SSID 16:Ericsson2.4G-2-1[0m [0;32mI (184850647) WIFI: SSID 17:Citrus 2.4[0m [0;32mI (184850647) WIFI: SSID 18:DIRECT-bb-HP M183 LaserJet[0m [0;32mI (184850657) WIFI: SSID 19:ThomasWifi[0m [0;32mI (184850667) WIFI: SSID 20:HannonLaw[0m [0;32mI (184850667) WIFI: SSID 21:Linksys08645-guest[0m I (184850697) wifi:new:<2,0>, old:<2,0>, ap:<255,255>, sta:<2,0>, prof:1 I (184850697) wifi:state: init -> auth (b0) I (184850707) wifi:state: auth -> assoc (0) I (184850717) wifi:state: assoc -> run (10) I (184850717) wifi:state: run -> init (ea0) I (184850717) wifi:new:<2,0>, old:<2,0>, ap:<255,255>, sta:<2,0>, prof:1 I (184850717) wifi:new:<2,0>, old:<2,0>, ap:<255,255>, sta:<2,0>, prof:1 [0;32mI (184850737) WIFI: Disconnected from wifi:14[0m

espxiehang commented 3 years ago

Hi @robertoimai , What is the encryption method of router?

robertoimai commented 3 years ago

WPA2-PSK

espxiehang commented 3 years ago

Hi @roamingthings , Can you give me a detailed log? You need to enable the following options.

idf.py menuconfig
Component config  ---> Wi-Fi  ---> [*] Enable WiFi debug log
                                   [*]     WiFi debug log submodule
                                   [*]         WiFi Debug Log Submodule Conn
Component config  ---> Log output  ---> Default log verbosity (Debug) 
Component config  ---> Supplicant  ---> [*] Print debug messages from WPA Supplicant

robertoimai commented 3 years ago

This is the new sdkconfig sdkconfig.txt I didn't see anything different on the log related to wifi when it made the initial connection. It is connected at the moment. I will let it run until it disconnects. Last time it took about 75hrs. I (7658) wifi:wifi driver task: 3ffd0608, prio:23, stack:6656, core=0 I (7758) wifi:wifi firmware version: 1865b55 I (7758) wifi:wifi certification version: v7.0 I (7758) wifi:config NVS flash: enabled I (7768) wifi:config nano formating: disabled I (7778) wifi:Init data frame dynamic rx buffer num: 24 I (7778) wifi:Init management frame dynamic rx buffer num: 24 I (7778) wifi:Init management short buffer num: 32 I (7788) wifi:Init static tx buffer num: 16 I (7788) wifi:Init tx cache buffer num: 32 I (7788) wifi:Init static rx buffer size: 1600 I (7798) wifi:Init static rx buffer num: 8 I (7798) wifi:Init dynamic rx buffer num: 24 I (7808) wifi_init: rx ba win: 16 I (7808) wifi_init: tcpip mbox: 32 I (7818) wifi_init: udp mbox: 6 I (7818) wifi_init: tcp mbox: 6 I (7818) wifi_init: tcp tx win: 5744 I (7828) wifi_init: tcp rx win: 5744 I (7828) wifi_init: tcp mss: 1436 I (7838) wifi_init: WiFi/LWIP prefer SPIRAM I (7838) WIFI: Already provisioned, starting Wi-Fi STA D (7848) efuse: coding scheme 0 D (7848) efuse: coding scheme 0 D (7848) efuse: coding scheme 0 D (7848) efuse: coding scheme 0 D (7848) efuse: coding scheme 0 D (7858) efuse: coding scheme 0 D (7858) efuse: coding scheme 0 D (7868) efuse: coding scheme 0 D (7868) efuse: coding scheme 0 D (7868) efuse: coding scheme 0 D (7868) efuse: coding scheme 0 D (7878) efuse: coding scheme 0 D (7878) efuse: coding scheme 0 D (7878) efuse: coding scheme 0 I (7888) wifi:mode : sta (fc:f5:c4:3c:f0:04) G2_CAL_0 I (7898) WIFI: STA Start I (7898) WIFI: Scanning for wifi networks... I (7908) SOUND: Finished: /spiffs/blank.mp3 I (7908) SOUND: Playing: /spiffs/test_mode.mp3 I (8798) SOUND: Finished: /spiffs/test_mode.mp3 I (8798) SOUND: Playing: /spiffs/please_enter_passcode.mp3 I (10018) WIFI: Scan Done I (10018) WIFI: RAM left 4193588 I (10018) WIFI: provisioned: 1 I (10018) WIFI: SSID 0:Azena F I (10018) WIFI: Attempting to connect to wifi Azena F I (10038) WIFI: SSID 1:Azena Guest I (10038) WIFI: SSID 2:PFF-2.4G I (10038) WIFI: SSID 3:DIRECT-C5-HP OfficeJet Pro 8710 I (10048) WIFI: SSID 4:PFF-2.4G_RPT I (10048) WIFI: SSID 5:PAD2 I (10048) WIFI: SSID 6:PAD5 I (10048) WIFI: SSID 7:BridgeWC I (10058) WIFI: SSID 8:GronowskiLaw I (10058) WIFI: SSID 9:DIRECT-ba-HP M277 LaserJet I (10058) WIFI: SSID 10:DIRECT-3e-HP M118 LaserJet I (10068) WIFI: SSID 11:Ericsson2.4G-2-1 I (10078) WIFI: SSID 12:Citrus 2.4 I (10088) WIFI: SSID 13:CBCI-748D-2.4 I (10088) WIFI: SSID 14:TP-LINK_2.4GHz_6E5BB5 I (10088) WIFI: SSID 15:VAAK LLP I (10098) WIFI: SSID 16:JohnsonLaw I (10098) WIFI: SSID 17:evanjuliet-2.4 I (10098) WIFI: SSID 18:Pocklingtonlaw I (10108) WIFI: SSID 19:HP-Print-5B-ENVY 4500 series I (10278) wifi:new:<2,0>, old:<1,0>, ap:<255,255>, sta:<2,0>, prof:1 I (10478) SOUND: Finished: /spiffs/please_enter_passcode.mp3 I (10668) wifi:state: init -> auth (b0) I (10688) wifi:state: auth -> assoc (0) I (10698) wifi:state: assoc -> run (10) I (10718) wifi:connected with Azena F, aid = 4, channel 2, BW20, bssid = cc:32:e5:4a:72:45 I (10718) wifi:security: WPA2-PSK, phy: bgn, rssi: -35 I (10718) wifi:pm start, type: 1

I (10738) WIFI: Connected to wifi network Azena F I (10778) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (11558) esp_netif_handlers: sta ip: 192.168.0.214, mask: 255.255.255.0, gw: 192.168.0.1

espxiehang commented 3 years ago

Hi @robertoimai , The WiFi connection failed four handshakes. So I want to look at the print log of the WPA section when the connection fails. I see that your sdkconfig configuration is correct, but I don't see the print log in the WPA section. Can you check it? Here is the print log for four handshakes

D (29385) wifi:start 10s connect timer for 4 way handshake
D (29445) wifi:rsn valid: gcipher=3 ucipher=3 akm=5
D (29485) wpa: IEEE 802.1X RX: version=1 type=3 length=95
D (29485) wpa:   EAPOL-Key type=2
D (29485) wpa:   key_info 0x8a (ver=2 keyidx=0 rsvd=0 Pairwise Ack)
D (29485) wpa:   key_length=16 key_data_length=0
D (29495) wpa: WPA: RX EAPOL-Key - hexdump(len=99):
D (29495) wpa: 01 03 00 5f 02 00 8a 00 10 00 00 00 00 00 00 00 
D (29505) wpa: 01 88 51 8d 8c 0d 70 5f 26 c9 54 52 eb 5c ca 5f 
D (29505) wpa: 30 c1 79 cc f2 17 87 0f 4d ba 28 e8 5e 21 e2 64 
D (29515) wpa: cd 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
D (29525) wpa: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
D (29525) wpa: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
D (29535) wpa: 00 00 00 
D (29535) wpa: WPA 1/4-Way Handshake
D (29535) wpa: RSN: msg 1/4 key data - hexdump(len=0):
D (29545) wpa: WPA: PTK derivation - A1=24:0a:c4:09:84:ec A2=60:38:e0:d1:6d:dd
D (29555) wpa: WPA: PMK - hexdump(len=32):

robertoimai commented 3 years ago

My mistake.... I had forgotten I set info on my code. Here it is a successful log and I'll post another when it fails: `D (12058) wifi:clear blacklist I (12058) WIFI: Attempting to connect to wifi Azena F D (12058) wifi:Start wifi connect D (12068) wifi:connect status 0 -> 0 D (12068) wifi:connect chan=0 D (12068) wifi:first chan=1 D (12068) wifi:connect status 0 -> 1 D (12078) wifi:filter: set rx policy=3 D (12078) wifi:clear scan ap list D (12078) wifi:start scan: type=0x50f, priority=2, cb=0x401b2b04, arg=0x0, ss_state=0x1, time=2535293, index=0 0x401b2b04: cnx_start_handoff_cb at ??:?

D (12088) wifi:perform scan: ss_state=0x9, chan<1,0>, dur<0,120> I (12098) WIFI: SSID 1:Azena Guest I (12098) WIFI: SSID 2:DIRECT-C5-HP OfficeJet Pro 8710 I (12108) WIFI: SSID 3:PFF-2.4G I (12108) WIFI: SSID 4:PFF-2.4G_RPT I (12118) WIFI: SSID 5:GORDON REESE guest I (12118) WIFI: SSID 6:GORDON REESE DESIGN BUILD I (12118) WIFI: SSID 7:BridgeWC I (12128) WIFI: SSID 8:GronowskiLaw I (12138) WIFI: SSID 9:DIRECT-3e-HP M118 LaserJet I (12138) WIFI: SSID 10:DIRECT-ba-HP M277 LaserJet I (12148) WIFI: SSID 11:Cappo-2.4 I (12148) WIFI: SSID 12:Citrus 2.4 I (12148) WIFI: SSID 13:PAD5 I (12158) WIFI: SSID 14:PAD2 I (12158) WIFI: SSID 15:JohnsonLaw I (12158) WIFI: SSID 16:CBCI-748D-2.4 I (12168) WIFI: SSID 17:VAAK LLP I (12168) WIFI: SSID 18:ThomasWifi I (12168) WIFI: SSID 19:WTP-Guest I (12188) WIFI: SSID 20:TP-LINK_2.4GHz_6E5BB5 D (12218) wifi:scan end: arg=0x0, status=0, ss_state=0x3 D (12218) wifi:perform scan: ss_state=0x9, chan<2,0>, dur<0,120> D (12218) wifi:rsn valid: gcipher=1 ucipher=3 akm=5

D (12218) wifi:profile match: ss_state=0x7 D (12238) wifi:rsn valid: gcipher=1 ucipher=3 akm=5

D (12238) wifi:set max rate: from to D (12238) wifi:sig_b=0, sig_g=0, sig_n=0, max_b=22, max_g=108, max_n=144 D (12248) wifi:profile match: ss_state=0x7 D (12248) wifi:rsn valid: gcipher=1 ucipher=3 akm=5

D (12258) wifi:profile match: ss_state=0x7 D (12318) wifi:rsn valid: gcipher=1 ucipher=3 akm=5

D (12318) wifi:profile match: ss_state=0x7 D (12338) wifi:scan end: arg=0x0, status=0, ss_state=0x7 D (12338) wifi:find first mathched ssid, scan done D (12338) wifi:filter: set rx policy=4 D (12338) wifi:first chan=1 D (12348) wifi:handoff_cb: status=0 D (12348) wifi:ap found, mac=cc:32:e5:4a:72:45 D (12358) wifi:new_bss=0x3ffc6cb8, cur_bss=0x0, new_chan=<2,0>, cur_chan=1 D (12368) wifi:filter: set rx policy=5 I (12368) wifi:new:<2,0>, old:<1,0>, ap:<255,255>, sta:<2,0>, prof:1 D (12378) wifi:connect_op: status=0, auth=5, cipher=3 D (12378) wifi:auth mode is not none D (12768) wifi:connect_bss: auth=1, reconnect=0 I (12768) wifi:state: init -> auth (b0) D (12768) wifi:start 1s AUTH timer D (12768) wifi:clear scan ap list D (12768) wifi:rsn valid: gcipher=1 ucipher=3 akm=5

D (12788) wifi:rsn valid: gcipher=1 ucipher=3 akm=5

D (12798) wifi:recv auth: seq=2, status=0 I (12808) wifi:state: auth -> assoc (0) D (12808) wifi:restart connect 1s timer for assoc D (12808) wifi:recv assoc: type=0x10 D (12808) wifi:filter: set rx policy=6 I (12808) wifi:state: assoc -> run (10) D (12828) wifi:start 10s connect timer for 4 way handshake D (12828) wpa: IEEE 802.1X RX: version=2 type=3 length=95

D (12828) wpa: EAPOL-Key type=2

D (12838) wpa: key_info 0x8a (ver=2 keyidx=0 rsvd=0 Pairwise Ack)

D (12838) wpa: key_length=16 key_data_length=0

D (12848) wpa: WPA: RX EAPOL-Key - hexdump(len=99): D (12848) wpa: 02 03 00 5f 02 00 8a 00 10 00 00 00 00 00 00 00 D (12848) wpa: 01 44 5f c3 85 fc 74 1c 05 d9 a1 be 0f 96 12 24 D (12858) wpa: fe 2e 66 b4 b1 ea 5d 0f 0c c9 73 f5 13 8e 82 66 D (12868) wpa: 10 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 D (12878) wpa: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 D (12878) wpa: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 D (12888) wpa: 00 00 00 D (12888) wpa: WPA 1/4-Way Handshake

D (12888) wpa: RSN: msg 1/4 key data - hexdump(len=0): D (12898) wpa: WPA: PTK derivation - A1=fc:f5:c4:3c:f0:04 A2=cc:32:e5:4a:72:45

D (12898) wpa: WPA: PMK - hexdump(len=32): D (12908) wpa: d8 02 56 70 60 84 35 25 48 77 cd 74 83 36 43 35 D (12918) wpa: 12 b4 37 21 34 d3 1b 90 2b 43 8f f8 05 62 6e 22 D (12928) wpa: WPA: PTK - hexdump(len=48): D (12928) wpa: c7 1a 01 ef 74 b7 5e c6 1b ef 34 bf e5 9a 1f c5 D (12928) wpa: 3e fa 16 fa 3b 19 ae 1f 74 b9 46 6c 1c a6 45 88 D (12938) wpa: 43 45 0d 09 ef 6e 2b 1f bd af d4 cf 2d 8c e2 f4 D (12938) wpa: WPA: WPA IE for msg 2/4

hexdump(len=22): D (12948) wpa: 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 D (12948) wpa: 00 0f ac 02 00 00 D (12958) wpa: WPA Send EAPOL-Key 2/4

D (12958) wpa: WPA: TX EAPOL-Key - hexdump(len=121): D (12958) wpa: 01 03 00 75 02 01 0a 00 00 00 00 00 00 00 00 00 D (12978) wpa: 01 07 1b 5f 6b 42 e5 65 37 45 57 27 56 db a9 0d D (12978) wpa: fd 33 11 8e 16 8a 21 cf c3 00 6b 43 b5 bc cb 54 D (12988) wpa: 5b 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 D (12988) wpa: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 D (12998) wpa: 00 47 bd 66 ff 79 62 1f 90 d5 7e 23 71 65 97 22 D (12998) wpa: 09 00 16 30 14 01 00 00 0f ac 02 01 00 00 0f ac D (13008) wpa: 04 01 00 00 0f ac 02 00 00 D (13018) wifi:rsn valid: gcipher=1 ucipher=3 akm=5

D (13018) wifi:rsn valid: gcipher=1 ucipher=3 akm=5

D (13028) wpa: IEEE 802.1X RX: version=2 type=3 length=199

D (13028) wpa: EAPOL-Key type=2

D (13038) wpa: key_info 0x13ca (ver=2 keyidx=0 rsvd=0 Pairwise Install Ack MIC Secure Encr)

D (13048) wpa: key_length=16 key_data_length=104

D (13048) wpa: WPA: RX EAPOL-Key - hexdump(len=203): D (13058) wpa: 02 03 00 c7 02 13 ca 00 10 00 00 00 00 00 00 00 D (13058) wpa: 02 44 5f c3 85 fc 74 1c 05 d9 a1 be 0f 96 12 24 D (13068) wpa: fe 2e 66 b4 b1 ea 5d 0f 0c c9 73 f5 13 8e 82 66 D (13068) wpa: 10 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 D (13078) wpa: 00 dc 96 01 00 00 00 00 00 00 00 00 00 00 00 00 D (13078) wpa: 00 90 80 74 d3 89 27 e4 ce fb d2 c0 8e 23 99 fe D (13098) wpa: d9 00 68 13 ce 61 84 ab 20 e6 3b 9a 13 ef 83 93 D (13098) wpa: b6 4a a9 41 09 4d 95 1f 96 09 97 d0 0c dd c6 76 D (13108) wpa: 78 0a 55 a4 73 77 51 ed 6a f6 68 2e 24 9d bf e6 D (13108) wpa: 8e f8 15 3a 65 fa 9a 01 41 5a d1 37 ae 10 b3 ca D (13118) wpa: 3a 26 49 89 bc 60 e8 d2 fa d9 c2 3d 82 83 5d 32 D (13118) wpa: e0 b5 00 5e fd 21 13 46 9c 74 4a ca 54 9b 8a 13 D (13128) wpa: a3 4f d5 87 15 38 cf 83 ff 4d 3d D (13128) wpa: WPA 3/4-Way Handshake

D (13138) wpa: WPA: No WPA/RSN IE for this AP known. Trying to get from scan results

D (13148) wpa: WPA: Found the current AP from updated scan results

D (13148) wpa: tx 4/4 txcb_flags=8192

D (13158) wpa: WPA Send EAPOL-Key 4/4

D (13158) wpa: WPA: TX EAPOL-Key - hexdump(len=99): D (13158) wpa: 01 03 00 5f 02 03 0a 00 00 00 00 00 00 00 00 00 D (13168) wpa: 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 D (13168) wpa: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 D (13178) wpa: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 D (13178) wpa: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 D (13198) wpa: 00 3b 29 b7 8f c9 63 87 10 5a 36 f0 d2 17 43 45 D (13198) wpa: df 00 00 D (13198) wifi:rsn valid: gcipher=1 ucipher=3 akm=5

D (13208) wifi:rsn valid: gcipher=1 ucipher=3 akm=5

D (13218) wpa: WPA: Installing PTK to the driver.

D (13218) wpa: WPA: Installing GTK to the driver (keyidx=1 tx=0 len=32).

D (13228) wpa: WPA: Key negotiation completed with cc:32:e5:4a:72:45 [PTK=CCMP GTK=TKIP]

I (13228) wifi:connected with Azena F, aid = 2, channel 2, BW20, bssid = cc:32:e5:4a:72:45 I (13238) wifi:security: WPA2-PSK, phy: bgn, rssi: -42 D (13238) wifi:remove all except cc:32:e5:4a:72:45 from rc list D (13248) wifi:clear blacklist D (13248) wifi:filter: set rx policy=7 I (13248) wifi:pm start, type: 1

D (13248) wifi:Send sta connected event D (13268) wifi:connect status 1 -> 5 D (13268) wifi:obss scan is disabled D (13268) wifi:start obss scan: obss scan is stopped I (13278) wifi:AP's beacon interval = 102400 us, DTIM period = 1 D (13268) event: running post WIFI_EVENT:4 with handler 0x4015a588 and context 0x3ffe1e38 on loop 0x3ffdcfc8 0x4015a588: wifi_default_action_sta_connected at C:/esp/esp-idf/components/esp_wifi/src/wifi_default.c:88

D (13288) esp_netif_handlers: esp_netif action connected with netif0x3ffe15e4 from event_id=4 D (13288) esp_netif_lwip: check: remote, if=0x3ffe15e4 fn=0x40152544 0x40152544: esp_netif_up_api at C:/esp/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:1131

D (13308) esp_netif_lwip: esp_netif_up_api esp_netif:0x3ffe15e4 D (13308) esp_netif_lwip: check: local, if=0x3ffe15e4 fn=0x40152d78 0x40152d78: esp_netif_update_default_netif_lwip at C:/esp/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:163

D (13318) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3ffe15e4 D (13328) esp_netif_lwip: call api in lwip: ret=0x0, give sem D (13328) esp_netif_lwip: check: remote, if=0x3ffe15e4 fn=0x40152104 0x40152104: esp_netif_dhcpc_start_api at C:/esp/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:929

D (13328) esp_netif_lwip: esp_netif_dhcpc_start_api esp_netif:0x3ffe15e4 D (13338) esp_netif_lwip: esp_netif_start_ip_lost_timer esp_netif:0x3ffe15e4 D (13358) esp_netif_lwip: if0x3ffe15e4 start ip lost tmr: no need start because netif=0x3ffe1668 interval=120 ip=0 D (13358) esp_netif_lwip: starting dhcp client D (13368) esp_netif_lwip: call api in lwip: ret=0x0, give sem D (13368) event: running post WIFI_EVENT:4 with handler 0x400e77a8 and context 0x3ffe3cc4 on loop 0x3ffdcfc8 0x400e77a8: event_handler at c:\users\owner\dropbox\azena\glass2\esp32\azena_glass2_production\build/../main/wifi.c:134

I (13378) WIFI: Connected to wifi network Azena F D (14168) esp_netif_lwip: esp_netif_dhcpc_cb lwip-netif:0x3ffe1668 D (14168) esp_netif_lwip: if0x3ffe15e4 ip changed=1 D (14168) event: running post IP_EVENT:0 with handler 0x4015a3a4 and context 0x3ffe1eec on loop 0x3ffdcfc8 0x4015a3a4: wifi_default_action_sta_got_ip at C:/esp/esp-idf/components/esp_wifi/src/wifi_default.c:128

D (14178) wifi_init_default: Got IP wifi default handler entered D (14188) esp_netif_handlers: esp_netif action got_ip with netif0x3ffe15e4 from event_id=0 I (14188) esp_netif_handlers: sta ip: 192.168.0.214, mask: 255.255.255.0, gw: 192.168.0.1 D (14208) event: running post IP_EVENT:0 with handler 0x400e77a8 and context 0x3ffe3cdc on loop 0x3ffdcfc8 0x400e77a8: event_handler at c:\users\owner\dropbox\azena\glass2\esp32\azena_glass2_production\build/../main/wifi.c:134`

espxiehang commented 3 years ago

@robertoimai , Yes, please use this version to reproduce the issue.

robertoimai commented 3 years ago

This is what I get when the disconnect happens: D (3770777) wpa: TKIP MIC failure occur [0m D (3770777) wpa: WPA: Sending EAPOL-Key Request (error=1 pairwise=0 ptk_set=1 len=99)[0m D (3770777) wpa: WPA: TX EAPOL-Key - hexdump(len=99):[0m D (3770787) wpa: 01 03 00 5f 02 0f 02 00 00 00 00 00 00 00 00 00 [0m D (3770787) wpa: 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [0m D (3770797) wpa: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [0m D (3770797) wpa: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [0m D (3770817) wpa: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [0m D (3770817) wpa: 00 f8 c0 f1 c9 78 18 22 46 6a a4 79 13 33 3b a3 [0m D (3770827) wpa: f8 00 00 [0m D (3770827) wpa: TKIP MIC failure occur [0m D (3770827) wpa: WPA: Sending EAPOL-Key Request (error=1 pairwise=0 ptk_set=1 len=99)[0m D (3770837) wpa: WPA: TX EAPOL-Key - hexdump(len=99):[0m D (3770847) wpa: 01 03 00 5f 02 0f 02 00 00 00 00 00 00 00 00 00 [0m D (3770847) wpa: 03 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [0m D (3770857) wpa: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [0m D (3770857) wpa: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [0m D (3770867) wpa: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [0m D (3770867) wpa: 00 ec f9 ce 11 ff 20 2a f6 c9 ca a0 20 5d 4b bd [0m D (3770877) wpa: 6e 00 00 [0m D (3770877) wpa: TKIP countermeasures started [0m D (3770907) wpa: TKIP MIC failure occur [0m D (3770907) wpa: WPA: Sending EAPOL-Key Request (error=1 pairwise=0 ptk_set=1 len=99)[0m D (3770907) wpa: WPA: TX EAPOL-Key - hexdump(len=99):[0m D (3770917) wpa: 01 03 00 5f 02 0f 02 00 00 00 00 00 00 00 00 00 [0m D (3770917) wpa: 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [0m D (3770927) wpa: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [0m D (3770927) wpa: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [0m D (3770937) wpa: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [0m D (3770947) wpa: 00 03 22 f6 c0 ee f9 04 bd d2 70 77 69 82 d0 74 [0m D (3770957) wpa: 8c 00 00 [0m D (3770957) wpa: TKIP countermeasures started [0m D (3770967) wpa: TKIP MIC failure occur [0m D (3770967) wpa: WPA: Sending EAPOL-Key Request (error=1 pairwise=0 ptk_set=1 len=99)[0m D (3770967) wpa: WPA: TX EAPOL-Key - hexdump(len=99):[0m D (3770977) wpa: 01 03 00 5f 02 0f 02 00 00 00 00 00 00 00 00 00 [0m D (3770977) wpa: 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [0m D (3770987) wpa: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [0m D (3770997) wpa: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [0m D (3771007) wpa: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [0m D (3771007) wpa: 00 86 74 23 19 7b 93 bd ad 02 e3 54 e2 4f 88 fa [0m D (3771017) wpa: a7 00 00 [0m D (3771017) wpa: TKIP countermeasures started [0m D (3771027) wpa: TKIP MIC failure occur [0m D (3771027) wpa: WPA: Sending EAPOL-Key Request (error=1 pairwise=0 ptk_set=1 len=99)[0m D (3771027) wpa: WPA: TX EAPOL-Key - hexdump(len=99):[0m D (3771037) wpa: 01 03 00 5f 02 0f 02 00 00 00 00 00 00 00 00 00 [0m D (3771037) wpa: 06 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [0m D (3771057) wpa: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [0m D (3771057) wpa: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [0m D (3771067) wpa: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [0m D (3771067) wpa: 00 57 65 70 54 39 84 5c f4 94 ea c1 5f d9 29 5d [0m D (3771077) wpa: a9 00 00 [0m D (3771077) wpa: TKIP countermeasures started [0m D (3771087) wpa: TKIP MIC failure occur [0m D (3771087) wpa: WPA: Sending EAPOL-Key Request (error=1 pairwise=0 ptk_set=1 len=99)[0m D (3771087) wpa: WPA: TX EAPOL-Key - hexdump(len=99):[0m D (3771107) wpa: 01 03 00 5f 02 0f 02 00 00 00 00 00 00 00 00 00 [0m D (3771107) wpa: 07 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [0m D (3771117) wpa: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [0m D (3771117) wpa: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [0m D (3771127) wpa: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [0m D (3771127) wpa: 00 8d 74 e3 61 57 3a cb 4d 52 6d 24 fb ac 0c 69 [0m D (3771137) wpa: 0a 00 00 [0m D (3771137) wpa: TKIP countermeasures started [0m D (3771157) wifi:recv deauth, reason=0x6 I (3771157) wifi:state: run -> init (6c0) D (3771157) wifi:recv deauth/disassoc, stop beacon/connect timer D (3771167) wifi:connect status 5 -> 4 D (3771167) wifi:sta leave I (3771167) wifi:pm stop, total sleep time: 3176618451 us / 3759518412 us

D (3771177) wifi:stop CSA timer D (3771187) wifi:remove cc:32:e5:4a:72:45 from rc list I (3771187) wifi:new:<2,0>, old:<2,0>, ap:<255,255>, sta:<2,0>, prof:1 D (3771197) wifi:filter: set rx policy=8 D (3771197) wifi:Send disconnect event, reason=6, AP number=0 D (3771197) event: running post WIFI_EVENT:5 with handler 0x4015a570 and context 0x3ffe1eb0 on loop 0x3ffe132c[0m D (3771207) esp_netif_handlers: esp_netif action disconnected with netif0x3ffe1650 from event_id=5[0m D (3771217) esp_netif_lwip: check: remote, if=0x3ffe1650 fn=0x40152594 [0m D (3771227) esp_netif_lwip: esp_netif_down_api esp_netif:0x3ffe1650[0m D (3771237) esp_netif_lwip: esp_netif_dhcpc_cb lwip-netif:0x3ffe16c4[0m D (3771237) esp_netif_lwip: esp_netif_start_ip_lost_timer esp_netif:0x3ffe1650[0m D (3771247) esp_netif_lwip: if0x3ffe1650 start ip lost tmr: interval=120[0m D (3771247) esp_netif_lwip: esp_netif_start_ip_lost_timer esp_netif:0x3ffe1650[0m D (3771257) esp_netif_lwip: if0x3ffe1650 start ip lost tmr: already started[0m D (3771267) esp_netif_lwip: check: local, if=0x3ffe1650 fn=0x40152d78 [0m D (3771277) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3ffe1650[0m D (3771287) esp_netif_lwip: call api in lwip: ret=0x0, give sem[0m D (3771287) event: running post WIFI_EVENT:5 with handler 0x400e77a8 and context 0x3ffe3d14 on loop 0x3ffe132c[0m [0;31mE (3771287) aws_iot: failed! mbedtls_ssl_write returned -0x4e[0m [0;32mI (3771297) SOUND: Send sound queue: 146-1[0m [0;33mW (3771327) WIFI: MQTT Disconnect[0m [0;32mI (3771327) WIFI: Trying to reconnect to AWS IoT.[0m [0;32mI (3771347) SOUND: Playing: /spiffs/wifi_disconnected.mp3[0m [0;32mI (3771347) WIFI: Disconnected from wifi:6[0m [0;32mI (3771357) WIFI: connection_retry: 1[0m [0;32mI (3772327) WIFI: MQTT task stopping...[0m

espxiehang commented 3 years ago

Hi @robertoimai , Thank you for your information. After this isue occurs, can you restart esp32 to connect successfully? Is there such a issue when other WiFi devices connect to this AP?

robertoimai commented 3 years ago

Yes, rebooting will let the esp32 reconnect and everything work fine until the next disconnect. We have several computers, laptops and cell phones connected to the same network and they never see any problems.

vwvierhundertzwoelf commented 3 years ago

Hi, i got the same Problem with our corporate WiFi. We also use WPA2-PSK and i tried it with D-LINK and Netgear routers. The IDF Version we use is 3.40200.210118. In our case the ESP loses connection every 2 or 3 minutes with the same error code "TKIP MIC failure occur". When i disable WMM in my router the error does not occur and everything works fine, but that is really slowing down the WiFi speed.

`D (178711) wpa: TKIP MIC failure occur

D (178711) wpa: WPA: Sending EAPOL-Key Request (error=1 pairwise=0 ptk_set=1 len=99) D (178711) wpa: WPA: TX EAPOL-Key - hexdump(len=99): D (178721) wpa: 01 03 00 5f 02 0f 02 00 00 00 00 00 00 00 00 00 D (178721) wpa: 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 D (178731) wpa: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 D (178741) wpa: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 D (178741) wpa: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 D (178751) wpa: 00 2f a9 32 97 bd 70 5f b0 6d fa 28 fb 9b 69 23 D (178751) wpa: b4 00 00 D (178761) wpa: TKIP MIC failure occur

D (178761) wpa: WPA: Sending EAPOL-Key Request (error=1 pairwise=0 ptk_set=1 len=99) D (178771) wpa: WPA: TX EAPOL-Key - hexdump(len=99): D (178771) wpa: 01 03 00 5f 02 0f 02 00 00 00 00 00 00 00 00 00 D (178781) wpa: 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 D (178791) wpa: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 D (178791) wpa: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 D (178801) wpa: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 D (178801) wpa: 00 a4 26 63 ac 94 3b db 6e 02 b8 3c df 33 59 df D (178811) wpa: bb 00 00 D (178811) wpa: TKIP countermeasures started

I (178831) wifi:state: run -> init (ec0) D (178831) wifi:recv deauth/disassoc, stop beacon/connect timer D (178831) wifi:connect status 5 -> 4 D (178831) wifi:sta leave I (178841) wifi:pm stop, total sleep time: 135053037 us / 151924714 us

D (178841) wifi:stop CSA timer D (178851) wifi:remove 10:be:f5:b0:44:c0 from rc list I (178851) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:6 D (178861) wifi:filter: set rx policy=8 D (178861) wifi:Send disconnect event, reason=14, AP number=0 D (178871) event: running post WIFI_EVENT:5 with handler 0x400dadb4 and context 0x3ffba5dc on loop 0x3ffba184 D (178881) wifi:Start wifi connect D (178881) wifi:connect status 4 -> 0 D (178881) wifi:connect chan=0 D (178881) wifi:first chan=1 D (178891) wifi:connect status 0 -> 1 D (178891) wifi:filter: set rx policy=3 D (178891) wifi:clear scan ap list D (178901) wifi:start scan: type=0x50f, priority=2, cb=0x4015c1a0, arg=0x0, ss_state=0x1, time=176492394, index=0 D (178911) wifi:perform scan: ss_state=0x9, chan<1,0>, dur<0,120> D (178911) event: running post WIFI_EVENT:5 with handler 0x400f7d18 and context 0x3ffd6e3c on loop 0x3ffba184 D (178921) esp_netif_handlers: esp_netif action disconnected with netif0x3ffd6ba0 from event_id=5 D (178931) esp_netif_lwip: check: remote, if=0x3ffd6ba0 fn=0x400f5d9c

D (178941) esp_netif_lwip: esp_netif_down_api esp_netif:0x3ffd6ba0 D (178951) esp_netif_lwip: esp_netif_dhcpc_cb lwip-netif:0x3ffd6c04 E (178951) SOCKET: mbedtls_ssl_read returned -76 D (178951) esp_netif_lwip: esp_netif_start_ip_lost_timer esp_netif:0x3ffd6ba0 D (178961) esp_netif_lwip: if0x3ffd6ba0 start ip lost tmr: interval=120 D (178971) wifi:rsn valid: gcipher=1 ucipher=3 akm=5

D (178971) esp_netif_lwip: esp_netif_start_ip_lost_timer esp_netif:0x3ffd6ba0 D (178981) wifi:D (178981) esp_netif_lwip: if0x3ffd6ba0 start ip lost tmr: already started profile match: ss_state=0x7D (178991) esp_netif_lwip: check: local, if=0x3ffd6ba0 fn=0x400f695c

D (179001) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3ffd6ba0 D (179001) wifi:D (179011) esp_netif_lwip: call api in lwip: ret=0x0, give sem scan end: arg=0x0, status=0, ss_state=0x7 D (179021) wifi:find first mathched ssid, scan done D (179021) wifi:filter: set rx policy=4 D (179031) wifi:first chan=1 D (179031) wifi:handoff_cb: status=0 D (179031) wifi:ap found, mac=10:be:f5:b0:44:c0 D (179041) wifi:new_bss=0x3f800038, cur_bss=0x0, new_chan=<1,0>, cur_chan=1 D (179041) wifi:filter: set rx policy=5 I (179051) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:6 D (179051) wifi:connect_op: status=0, auth=5, cipher=3 D (179061) wifi:auth mode is not none D (179061) wifi:connect_bss: auth=1, reconnect=0 I (179061) wifi:state: init -> auth (b0) D (179071) wifi:start 1s AUTH timer D (179071) wifi:clear scan ap list D (179081) wifi:rsn valid: gcipher=1 ucipher=3 akm=5

D (179081) wifi:set max rate: from to D (179091) wifi:sig_b=0, sig_g=0, sig_n=0, max_b=22, max_g=108, max_n=144 I (179171) SOCKET: Seeding the random number generator D (179181) wifi:I (179181) SOCKET: Loading the CA root certificate... rsn valid: gcipher=1 ucipher=3 akm=5

I (179181) SOCKET: Setting up the SSL/TLS structure... I (179181) SOCKET: Setting hostname for TLS session... E (179191) SOCKET: mbedtls_net_connect returned -44 I (179201) SOCKET: Performing the SSL/TLS handshake... E (179201) SOCKET: mbedtls_ssl_handshake returned -0x45 I (179211) SOCKET: Setting hostname for TLS session... E (179211) SOCKET: mbedtls_net_connect returned -44 I (179221) SOCKET: Performing the SSL/TLS handshake... E (179231) SOCKET: mbedtls_ssl_handshake returned -0x45 D (179281) wifi:rsn valid: gcipher=1 ucipher=3 akm=5

D (179381) wifi:rsn valid: gcipher=1 ucipher=3 akm=5 `

mbratch commented 2 years ago

@robertoimai In the last comment is a link to a similar issue that I raised. I changed my event handler to continually try to reconnect for an indefinite period of time. It takes 40-60 seconds to re-establish the connection automatically in this case. I noticed your log sample covers about 23 seconds. It would be interesting to know if you could indeed eventually reconnect.

robertoimai commented 2 years ago

As far as I can remember, it was never able to reconnect. I've never found a solution for this, but I did get a different router that doesn't present this problem. We have been testing on this new router ever since, so I can't tell if it would reconnect or not.

AxelLin commented 2 years ago

@espxiehang

Any update?

It seems the function to print above error log was called after MIC failure, I'm not sure if the log is helpful or not. Or any additional information required?

espxiehang commented 2 years ago

Hi @AxelLin , After receiving a packet from the hardware, the software parses the header and throws away any wrong packets.

AxelLin commented 2 years ago

@espxiehang

Now there are 3 reports (running on different esp-idf version) regarding WIFI_REASON_MIC_FAILURE

v3.3.1: https://github.com/espressif/esp-idf/issues/5023 v4.2: This one v4.3: https://github.com/espressif/esp-idf/issues/7286

espxiehang commented 2 years ago

Hi @AxelLin , When the STA detects the received packet "mac_rx_ctrl- > rx_state == RX_TKIPMIC_ERR". wpa_michael_mic_failure is called.

AxelLin commented 2 years ago

@espxiehang I doubt because v3.3.1 and v4.3 just do not enable CONFIG_WPA_DEBUG_PRINT. They all got WIFI_REASON_MIC_FAILURE.

espxiehang commented 2 years ago

@AxelLin Refer to the above comment to set menuconfig. Is there a quick way to replicate that?I'm going to repeat the problem here

AxelLin commented 2 years ago

Hi @espxiehang

I got similar symptoms in customer's bug report. But the customer is not a technical guy so I cannot get more details. I cannot reproduce the issue in my environment (But I hit different issue in my test https://github.com/espressif/esp-idf/issues/7289)

At the moment, seems @mbratch has better chance to reproduce the MIC failure issue, see https://github.com/espressif/esp-idf/issues/7286

AxelLin commented 2 years ago

@espxiehang

Seems the discussions are focus on WIFI_REASON_MIC_FAILURE. But my question is as the subject line says that "Wifi disconnects and is unable to reconnect". The problem description says it led to stale. i.e. Any attempt to reconnect will also fail. (This is a BIG problem).

@robertoimai Is this still an issue with recent esp-idf?

robertoimai commented 2 years ago

I cannot confirm nor deny. I am still using the v4.2 and I am still using the new router, which has not given me this error anymore.

mbratch commented 2 years ago

When I was using an Apple Airport Extreme (A1408), I was getting this problem regularly. I could recover by recognizing the condition in my wifi event handler and continually retrying to connect for up to 60 seconds and it would eventually reconnect. However, for that period of time, the link was obviously down.

I have since changed routers. I am using now a TP-Link Archer C4000, and I have not seen the MIC problem using this router.

This is why the problem is not seen by everyone.

I still have my Apple Airport router I am willing to donate to someone on the ESP-IDF development team if they are willing to pursue the issue and cover the shipping of the router. :)

jack0c commented 2 years ago

@robertoimai @mbratch @AxelLin TKIP MIC error is used to detect attack: If a station get 2 TKIP MIC errors in a minute, it needs to disconnect from AP, and wait a minute until it can connect to the AP again. This is part of IEEE80211 standard.

mbratch commented 2 years ago

@jack0c I understand, but this is not functioning correctly and is not normal if it is regularly disrupting normal wifi lan service. This problem only occurs with certain wifi routers, e.g , my apple Airport Extreme.

vwvierhundertzwoelf commented 2 years ago

@jack0c @mbratch I found out that disabling WiFi Multimedia Management (WMM) in my Router solved the issue for all my esp32 and esp8266. But this limits the Bandwith of my 2.4GHz WiFi to 54mbit/s. So there seems to be a problem with the esp-idf implementation of WMM. With older routers i did not encouter the disconnecting issue at all. Is it possible to disable WMM in your Airport Extreme to verify my results?

mbratch commented 2 years ago

That's cool. But my router does not have that setting. And, technically, it is an older router. My particular model is several years old

AxelLin commented 1 year ago

@vwvierhundertzwoelf @robertoimai Please check if update your esp-idf fixed the issue or not. The fix "wpa_supplicant: try install gtk before send 2 of 2" is in master, v5.0, v4.4, v4.3 and v4.2 branches now. This change installs the gtk before sending the 2of2 which takes care of the race condition where station receives the data even before installing the new keys.(Packets decrypted using older key may cause mic error), see https://github.com/espressif/esp-idf/issues/7286#issuecomment-1260478802

Pabs84 commented 1 year ago

Hi all,

I have tested master branch and I confirm the behaviour changed: right now when it disconnects sporadically with MIC failure, it reconnects while older version failed to do so (any transfer led to MIC failure); I can tell there has been an improvement, I cannot understand though the root cause of this MIC failure; My device is being tested in WPA,WPA2,WPA3,WPA2-Enterprise; but there is one AP that is configured as WPA2 CCMP+TKIP that produce this failure; I tried to replicate the same issue with another AP of different brand and "same" settings and it just works on the latter one; I am available to provide any support on this topic because at the moment is problematic and I understand is hard to replicate immagine

mbratch commented 1 year ago

@Pabs84 that was basically what I had already done to work around the MIC failure. In my event handler, I detect the failure then try to reconnect. I'm able to reconnect automatically, but it takes 30-60 seconds before it's able to do so (it keeps retrying until it is successful). So the device loses wifi communications for 30-60 seconds.

So in this work around fix, I would suspect the same? Do you know how long it takes it to recover from the MIC failure?

Pabs84 commented 1 year ago

@mbratch, hi, with the older version it was basically never connecting for me, because every reconnection was failing with MIC failure. Right now the fix allows me to reconnect and after let say a minute I get another MIC failure, but the reconnection works and I can stay connected until the next failure. it looks to me that there is a frame the ESP32 does not understand and is the root cause for me; however I suggest you try the latest version; I checked v4.4.2 and the fix is not there just yet though, only master

Pabs84 commented 1 year ago

most logical would be that after a minute of no traffic the AP generates a frame based on the following: immagine and ESP32 does a reconnection cycle

jack0c commented 1 year ago

@mbratch @Pabs84 The fix in https://github.com/espressif/esp-idf/issues/7286#issuecomment-1260478802 just speed up to install new GTK. It can avoid some TKIP MIC error triggered by new GTK not installed but the frame encrypted with new GTK already received. It can reduce TKIP MIC error somehow. But TKIP MIC error triggered by other reason may still exist. We will try to reproduce the issues with the AP and configuration mentioned.

mhdong commented 1 year ago

Hi @Pabs84 Could you provide the router brand and model? We will try to reproduce this issue locally.

Pabs84 commented 1 year ago

Hi, I have tried to disable Wireless Multimedia U-APSD whatever feature, with no benefit. this serves to no help, but just to continue the discussion.

to @mhdong: My faulty AP is of brand "Alcatel-Lucent" / "Aruba". Model is APIN0207

to @jack0c: I understand. From my experiment it seems the patch "installs the gtk before sending the 2of2" mentioned in comment #7286 seems to being connected to what I see as the behaviour changes, but not fully solved.

Thanks for the support, I hope you can find the root cause

chegewara commented 1 year ago

Maybe someone can confirm this, but i just discovered that with v4.4.4 (arduino) WIFI_REASON_MIC_FAILURE may be reported with wrong wifi pass.

AxelLin commented 1 year ago

Hi, I have tried to disable Wireless Multimedia U-APSD whatever feature, with no benefit. this serves to no help, but just to continue the discussion.

to @mhdong: My faulty AP is of brand "Alcatel-Lucent" / "Aruba". Model is APIN0207

to @jack0c: I understand. From my experiment it seems the patch "installs the gtk before sending the 2of2" mentioned in comment #7286 seems to being connected to what I see as the behaviour changes, but not fully solved.

@Pabs84 What do you mean by "what I see as the behaviour changes, but not fully solved."? Which means this is still an issue?

Pabs84 commented 1 year ago

Hi, I have tried to disable Wireless Multimedia U-APSD whatever feature, with no benefit. this serves to no help, but just to continue the discussion. to @mhdong: My faulty AP is of brand "Alcatel-Lucent" / "Aruba". Model is APIN0207 to @jack0c: I understand. From my experiment it seems the patch "installs the gtk before sending the 2of2" mentioned in comment #7286 seems to being connected to what I see as the behaviour changes, but not fully solved.

@Pabs84 What do you mean by "what I see as the behaviour changes, but not fully solved."? Which means this is still an issue?

Hi @AxelLin, I have recently updated to ESP-IDF v5.0.1 and we are in the process of testing it. I will let you know if I still sporadically get MIC errors.

Pabs84 commented 1 year ago

Hi @AxelLin, I confirm that in rare conditions I can still get MIC errors. I have updated from ESP-IDF v5.0.1 to ESP-IDF v5.0.2 to check if the latest stable FW fix this with no luck. The strange thing is that it worked for weeks with no issues, and recently it stopped from working. The issue triggers within 10 seconds after a good connection. Traffic is fine until the sudden disconnection. I guess there is something on my network that triggers this, so my suggestion is to not test it as point to point. the settings are CCMP and group cipher is TKIP, which seems (with my ingenuity) to be the root cause.

AxelLin commented 1 year ago

@Pabs84 I think you need to provide debug build log: https://github.com/espressif/esp-idf/issues/6920#issuecomment-824599813 And capture the network packet if possible.

Pabs84 commented 11 months ago

@Pabs84 I think you need to provide debug build log: #6920 (comment) And capture the network packet if possible.

I am sorry, it did happen, but I cannot understand how to replicate this at will. If I ever manage to get my hands on the logs will give you more info.

Pabs84 commented 11 months ago

Hi @AxelLin, I have the logs with MIC_FAILURE. Can we continue using PMs?

AxelLin commented 11 months ago

Hi @AxelLin, I have the logs with MIC_FAILURE. Can we continue using PMs?

Sorry, I don't work for espressif. You may contact @mhdong @jack0c @espxiehang

mhdong commented 11 months ago

Hi @Pabs84 Please help upload the log with NIC_FAILURE to github. If it's convenient, I would like to add some debug logs later. Could you please help me reproduce them? I would greatly appreciate it.

Pabs84 commented 11 months ago

@mhdong Hi, I will not share logs with plaintext keys publicly in principle; I can share with espressif employees using PMs.

Xiehanxin commented 11 months ago

hi, @Pabs84, you can send it to the following email sales@espressif.com and include your LOG. Please make sure to mention the GitHub link and provide a brief description in the email. Alternatively, you can notify me (@mention) after sending the email, that we can get the information as soon as possible

Xiehanxin commented 11 months ago

hi @Pabs84 I have received your e-mail, thanks for your sharing, we will analyze as soon as possible.

espressif / esp-idf