Wifi Connection fails (IDFGH-13058)

f-hoepfinger-hr-agrartechnik commented 1 week ago

Answers checklist.

[X] I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
[X] I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
[X] I have searched the issue tracker for a similar issue and not found a similar issue.

General issue report

Why can this happen ?

I (27479) wifi:removing station <50:02:91:8d:db:ec> after unsuccessful auth/assoc, AID = 0
W (27479) wifi:rm mis
I (27479) wifi:new:<1,0>, old:<1,1>, ap:<1,1>, sta:<0,0>, prof:1
D (27484) event: running post WIFI_EVENT:41 with handler 0x42016e0c and context 0x3fcc56a4 on loop 0x3fcc1d34
0x42016e0c: wifi_event_handler at /home/franz/git/hr/CTIS/CTIS/components/connect_wifi/wifi_connect.c:86

f-hoepfinger-hr-agrartechnik commented 1 week ago

D (17527) wifi:ap recv assoc/reassoc request
I (17527) wifi:new:<1,1>, old:<1,1>, ap:<1,1>, sta:<0,0>, prof:1
D (17528) wifi:bss=0x3c254018, resp=16 join
I (17530) wifi:station: d6:62:07:b3:e9:c3 join, AID=2, bgn, 40U
D (17535) wpa:   New STA
D (17538) wpa: add sm, index=0 bitmap=1
D (17542) wpa: init wpa sm=0x3c2543cc
D (17546) wpa: rsn_ie - hexdump(len=28):
D (17550) wpa: 30 1a 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 
D (17556) wpa: 00 0f ac 02 80 40 00 00 00 0f ac 06 
D (17561) wifi:join success bss=0x3c254018, ap send assoc response
D (17567) wpa: WPA: d6:62:07:b3:e9:c3 WPA_PTK entering state INITIALIZE

D (17573) wpa: wpa_auth_set_key : key idx  0 alg 0 vlan_id 0 key_len 0 key
D (17580) wpa: ELOOP: wpa_remove_ptk:1252 called to remove timer handler=0x42101030, removed count=0
0x42101030: wpa_rekey_ptk at /home/franz/esp-idf-v5.2.2/components/wpa_supplicant/src/ap/wpa_auth.c:262

D (17590) wpa: WPA: d6:62:07:b3:e9:c3 WPA_PTK_GROUP entering state IDLE

D (17596) wpa: WPA: d6:62:07:b3:e9:c3 WPA_PTK entering state AUTHENTICATION

D (17604) wpa: WPA: d6:62:07:b3:e9:c3 WPA_PTK entering state AUTHENTICATION2

D (17611) wpa: WPA: Re-initialize GMK/Counter on first station
D (17617) wpa: GMK - hexdump(len=32):
D (17621) wpa: d1 c4 b6 41 0e 79 44 83 56 99 aa c5 1c 66 2d 75 
D (17627) wpa: 6b 25 8e 07 1d 39 d7 68 4c 0e 32 5f 4b 58 c5 99 
D (17633) wpa: Key Counter - hexdump(len=32):
D (17637) wpa: 82 ad 47 34 b6 fc 95 4d 84 80 42 85 9b 5f 57 2b 
D (17643) wpa: 98 c2 e7 75 e6 67 8f c9 23 9e b4 54 b5 55 b8 fc 
D (17649) wpa: GTK - hexdump(len=32):
D (17653) wpa: 1f 36 c8 08 16 d5 81 c1 8e b4 e0 26 26 0c 6f af 
D (17659) wpa: 6e 8b b7 ba 70 a5 aa 4a e0 54 5d 04 26 dd 0d 50 
D (17665) wpa: IGTK - hexdump(len=16):
D (17669) wpa: b6 77 70 7b 75 32 b5 f2 a5 7c 7d 42 4f 10 9c 81 
D (17674) wpa: wpa_auth_set_key : key idx  1 alg 2 vlan_id 0 key_len 32 key
D (17682) wpa: wpa_auth_set_key : igtk idx 4
D (17686) wpa: WPA: Assign ANonce - hexdump(len=32):
D (17691) wpa: d0 32 c4 9e d6 82 16 f6 21 c6 79 6c ce cb 4e 02 
D (17697) wpa: 49 cc 7e f8 1b a3 07 27 3e 4f 9c 26 c8 e4 31 46 
D (17703) wpa: WPA: d6:62:07:b3:e9:c3 WPA_PTK entering state INITPSK

D (17709) wpa: WPA: d6:62:07:b3:e9:c3 WPA_PTK entering state PTKSTART

D (17716) wpa: wpa_auth=0x3c2482ac sm=0x3c2543cc  kdersc=0x0 kde=0x0 nounce=0x3c25441c kde_len=0 keyidx=0 encr=0 force=0
D (17727) wpa: WPA: Send EAPOL(version=2 secure=0 mic=0 ack=1 install=0 pairwise=1 kde_len=0 keyidx=0 encr=0)
D (17737) wpa: ELOOP: wpa_send_eapol:1212 called to remove timer handler=0x42100170, removed count=0
0x42100170: resend_eapol_handle at /home/franz/esp-idf-v5.2.2/components/wpa_supplicant/src/ap/wpa_auth.c:1184

D (17746) wpa: ELOOP: Added one timer from wpa_send_eapol:1213 to call 0x42100170, current order=0
0x42100170: resend_eapol_handle at /home/franz/esp-idf-v5.2.2/components/wpa_supplicant/src/ap/wpa_auth.c:1184

D (18746) wpa: ELOOP: Running timer fn:0x42100170 scheduled by wpa_send_eapol:1213 
0x42100170: resend_eapol_handle at /home/franz/esp-idf-v5.2.2/components/wpa_supplicant/src/ap/wpa_auth.c:1184

D (18747) wpa: resend eapol1
D (18747) wpa: WPA: d6:62:07:b3:e9:c3 WPA_PTK entering state PTKSTART

D (18753) wpa: wpa_auth=0x3c2482ac sm=0x3c2543cc  kdersc=0x0 kde=0x0 nounce=0x3c25441c kde_len=0 keyidx=0 encr=0 force=0
D (18764) wpa: WPA: Send EAPOL(version=2 secure=0 mic=0 ack=1 install=0 pairwise=1 kde_len=0 keyidx=0 encr=0)
D (18774) wpa: ELOOP: wpa_send_eapol:1212 called to remove timer handler=0x42100170, removed count=0
0x42100170: resend_eapol_handle at /home/franz/esp-idf-v5.2.2/components/wpa_supplicant/src/ap/wpa_auth.c:1184

D (18783) wpa: ELOOP: Added one timer from wpa_send_eapol:1213 to call 0x42100170, current order=0
0x42100170: resend_eapol_handle at /home/franz/esp-idf-v5.2.2/components/wpa_supplicant/src/ap/wpa_auth.c:1184

D (19783) wpa: ELOOP: Running timer fn:0x42100170 scheduled by wpa_send_eapol:1213 
0x42100170: resend_eapol_handle at /home/franz/esp-idf-v5.2.2/components/wpa_supplicant/src/ap/wpa_auth.c:1184

D (19784) wpa: resend eapol1
D (19784) wpa: WPA: d6:62:07:b3:e9:c3 WPA_PTK entering state PTKSTART

D (19790) wpa: wpa_auth=0x3c2482ac sm=0x3c2543cc  kdersc=0x0 kde=0x0 nounce=0x3c25441c kde_len=0 keyidx=0 encr=0 force=0
D (19801) wpa: WPA: Send EAPOL(version=2 secure=0 mic=0 ack=1 install=0 pairwise=1 kde_len=0 keyidx=0 encr=0)
D (19811) wpa: ELOOP: wpa_send_eapol:1212 called to remove timer handler=0x42100170, removed count=0
0x42100170: resend_eapol_handle at /home/franz/esp-idf-v5.2.2/components/wpa_supplicant/src/ap/wpa_auth.c:1184

D (19820) wpa: ELOOP: Added one timer from wpa_send_eapol:1213 to call 0x42100170, current order=0
0x42100170: resend_eapol_handle at /home/franz/esp-idf-v5.2.2/components/wpa_supplicant/src/ap/wpa_auth.c:1184

D (20820) wpa: ELOOP: Running timer fn:0x42100170 scheduled by wpa_send_eapol:1213 
0x42100170: resend_eapol_handle at /home/franz/esp-idf-v5.2.2/components/wpa_supplicant/src/ap/wpa_auth.c:1184

D (20820) wpa: resend eapol1
D (20820) wpa: WPA: d6:62:07:b3:e9:c3 WPA_PTK entering state PTKSTART

D (20826) wpa: wpa_auth=0x3c2482ac sm=0x3c2543cc  kdersc=0x0 kde=0x0 nounce=0x3c25441c kde_len=0 keyidx=0 encr=0 force=0
D (20837) wpa: WPA: Send EAPOL(version=2 secure=0 mic=0 ack=1 install=0 pairwise=1 kde_len=0 keyidx=0 encr=0)
D (20848) wpa: ELOOP: wpa_send_eapol:1212 called to remove timer handler=0x42100170, removed count=0
0x42100170: resend_eapol_handle at /home/franz/esp-idf-v5.2.2/components/wpa_supplicant/src/ap/wpa_auth.c:1184

D (20857) wpa: ELOOP: Added one timer from wpa_send_eapol:1213 to call 0x42100170, current order=0
0x42100170: resend_eapol_handle at /home/franz/esp-idf-v5.2.2/components/wpa_supplicant/src/ap/wpa_auth.c:1184

D (21857) wpa: ELOOP: Running timer fn:0x42100170 scheduled by wpa_send_eapol:1213 
0x42100170: resend_eapol_handle at /home/franz/esp-idf-v5.2.2/components/wpa_supplicant/src/ap/wpa_auth.c:1184

D (21857) wpa: resend eapol1
D (21857) wpa: WPA: d6:62:07:b3:e9:c3 WPA_PTK entering state PTKSTART

D (21863) wpa: WPA: d6:62:07:b3:e9:c3 WPA_PTK entering state DISCONNECT

D (21870) wpa: wpa_sta_disconnect STA d6:62:07:b3:e9:c3
D (21875) wifi:Removing node for station d6:62:07:b3:e9:c3
D (21881) wpa: WPA: d6:62:07:b3:e9:c3 WPA_PTK entering state DISCONNECTED

D (21888) wpa: WPA: d6:62:07:b3:e9:c3 WPA_PTK entering state INITIALIZE

D (21894) wpa: wpa_auth_set_key : key idx  0 alg 0 vlan_id 0 key_len 0 key
D (21901) wpa: ELOOP: wpa_remove_ptk:1252 called to remove timer handler=0x42101030, removed count=0
0x42101030: wpa_rekey_ptk at /home/franz/esp-idf-v5.2.2/components/wpa_supplicant/src/ap/wpa_auth.c:262

I (21931) wifi:station: d6:62:07:b3:e9:c3 leave, AID = 2, bss_flags is 34311266, bss:0x3c254018
I (21932) wifi:new:<1,0>, old:<1,1>, ap:<1,1>, sta:<0,0>, prof:1
D (21935) wpa: ELOOP: wpa_auth_sta_deinit:508 called to remove timer handler=0x42100170, removed count=0
0x42100170: resend_eapol_handle at /home/franz/esp-idf-v5.2.2/components/wpa_supplicant/src/ap/wpa_auth.c:1184

D (21944) wpa: del sm, index=0 bitmap=0
D (21948) wpa: wpa_free_sta_sm: free eapol=0x0

D (21953) event: running post WIFI_EVENT:41 with handler 0x42016e0c and context 0x3fcc56a4 on loop 0x3fcc1d34
0x42016e0c: wifi_event_handler at /home/franz/git/hr/CTIS/CTIS/components/connect_wifi/wifi_connect.c:86

I (24392) main: Core id: 0, prio: 1,  free heap: 8295136 bytes., minimum free heap: 8292068 bytes., minimum free stack: 1484 bytes.
I (32821) wifi:removing station <50:02:91:8d:db:ec> after unsuccessful auth/assoc, AID = 0
W (32822) wifi:rm mis
I (32822) wifi:new:<1,0>, old:<1,0>, ap:<1,1>, sta:<0,0>, prof:1
I (34394) main: Core id: 0, prio: 1,  free heap: 8294152 bytes., minimum free heap: 8292068 bytes., minimum free stack: 1484 bytes.
I (44396) main: Core id: 0, prio: 1,  free heap: 8294016 bytes., minimum free heap: 8292068 bytes., minimum free stack: 1484 bytes.
I (44446) wifi:removing station <d6:62:07:b3:e9:c3> after unsuccessful auth/assoc, AID = 0
W (44446) wifi:rm mis
I (44446) wifi:new:<1,0>, old:<1,0>, ap:<1,1>, sta:<0,0>, prof:1
I (54398) main: Core id: 0, prio: 1,  free heap: 8295036 bytes., minimum free heap: 8292068 bytes., minimum free stack: 1484 bytes.
I (61039) wifi:removing station <50:02:91:8d:db:ec> after unsuccessful auth/assoc, AID = 0
W (61039) wifi:rm mis
I (61039) wifi:new:<1,0>, old:<1,0>, ap:<1,1>, sta:<0,0>, prof:1

MaxwellAlan commented 1 week ago

Hi @f-hoepfinger-hr-agrartechnik

D (20820) wpa: resend eapol1 D (20820) wpa: WPA: d6:62:07:b3:e9:c3 WPA_PTK entering state PTKSTART D (20826) wpa: wpa_auth=0x3c2482ac sm=0x3c2543cc kdersc=0x0 kde=0x0 nounce=0x3c25441c kde_len=0 keyidx=0 encr=0 force=0 D (20837) wpa: WPA: Send EAPOL(version=2 secure=0 mic=0 ack=1 install=0 pairwise=1 kde_len=0 keyidx=0 encr=0) D (20848) wpa: ELOOP: wpa_send_eapol:1212 called to remove timer handler=0x42100170, removed count=0 0x42100170: resend_eapol_handle at /home/franz/esp-idf-v5.2.2/components/wpa_supplicant/src/ap/wpa_auth.c:1184 D (20857) wpa: ELOOP: Added one timer from wpa_send_eapol:1213 to call 0x42100170, current order=0 0x42100170: resend_eapol_handle at /home/franz/esp-idf-v5.2.2/components/wpa_supplicant/src/ap/wpa_auth.c:1184 D (21857) wpa: ELOOP: Running timer fn:0x42100170 scheduled by wpa_send_eapol:1213 0x42100170: resend_eapol_handle at /home/franz/esp-idf-v5.2.2/components/wpa_supplicant/src/ap/wpa_auth.c:1184 D (21857) wpa: resend eapol1 D (21857) wpa: WPA: d6:62:07:b3:e9:c3 WPA_PTK entering state PTKSTART D (21863) wpa: WPA: d6:62:07:b3:e9:c3 WPA_PTK entering state DISCONNECT

from the logs, we know that SoftAP send eapol 1/4 to station, but the station not reply eapol 2/4, please check the station side auth mode and password.

4-WAY-handshake

f-hoepfinger-hr-agrartechnik commented 1 week ago

it must be something in the Code:

https://github.com/espressif/esp-idf/tree/master/examples/wifi/softap_sta

this example works flawless on the same Hardware.

i will now implant the Example into my Project

espressif / esp-idf

Wifi Connection fails (IDFGH-13058) #14003

Answers checklist.

General issue report