WiFi STA fail to connect in enterprise AP.

User avatar
urbanze
Posts: 267
Joined: Sat Jun 10, 2017 9:55 pm
Location: Brazil

WiFi STA fail to connect in enterprise AP.

Postby urbanze » Wed Jul 15, 2020 4:53 pm

Hello guys, I need some help with "enterprise" WiFis.

With my home wifi or mobile AP (hosted from galaxy s8), esp32 always can connect correctly and get dhcp ip. However, here in my job (enterprise wifi), esp32 fail to connect OR fail to get DHCP or connect sucessfully. (random)

Please, help me to find WHY (or solution) to solve this problem. I have enabled all wifi log from menuconfig to help debug:

1. Here, ESP32 can connect to WiFi and receive DHCP sucessfully.

Code: Select all

I (3367) wifi: mode : sta (3c:71:bf:6e:a9:fc) + softAP (3c:71:bf:6e:a9:fd)
I (3374) wifi: filter: set rx policy=9
I (3377) wifi: ht20 freq=2412, chan=1
I (3384) wifi: Start wifi disconnect
I (3384) wifi: connect step 0 -> 0, status=0, err_time=0
I (3389) wifi: connect status 0 -> 0, step=0, err_time=0
I (3394) wifi: filter: set rx policy=8
I (3397) wifi: clear blacklist
I (3400) wifi: Start wifi connect
I (3403) wifi: connect step 0 -> 0, status=0, err_time=0
I (3408) wifi: connect chan=0
I (3411) wifi: nvs=0, ssid=SISTEL CONVIDADO, channel=255
I (3416) wifi: ssid=SISTEL CONVIDADO match nvs 0, channel=255
I (3421) wifi: first chan=1
I (3424) wifi: connect status 0 -> 1, step=0, err_time=0
I (3429) wifi: connect step 0 -> 1, status=1, err_time=0
I (3434) wifi: filter: set rx policy=3
I (3437) wifi: clear scan ap list
I (3440) wifi: start scan: type=0x50f, priority=2, cb=0x40126b98, arg=0x0, ss_state=0x1, time=239108, index=0
0x40126b98: cnx_start_handoff_cb at ??:?

I (3450) wifi: inter_channel_timeout: arg=0x0, ss_state=0x1
I (3455) wifi: perform scan: ss_state=0x9, chan<1,0>, dur<100,150>
I (3461) wifi: change: chan<1,0>, dur<100,150>
I (3465) wifi: enter start op, arg=0x3ffb5878
I (3469) wifi: scan operation: state=0x3, chan<1,0>, arg=0x3ffb5878, status=0
I (3476) wifi: scan specific ssid=SISTEL CONVIDADO
I (3481) wifi: start min timer
I (3484) wifi: start max timer
I (3636) wifi: scan end: arg=0x0, status=0, ss_state=0x3
I (3637) wifi: back home chan=<1,0>, current chan=<1,0>
I (3637) wifi: start scan timer
I (3668) wifi: oper_channel: arg=0x0 time=467114
I (3669) wifi: perform scan: ss_state=0x9, chan<2,0>, dur<100,150>
I (3669) wifi: change: chan<2,0>, dur<100,150>
I (3672) wifi: ht20 freq=2417, chan=2
I (3676) wifi: enter start op, arg=0x3ffb5878
I (3679) wifi: scan operation: state=0x3, chan<2,0>, arg=0x3ffb5878, status=0
I (3686) wifi: scan specific ssid=SISTEL CONVIDADO
I (3691) wifi: start min timer
I (3693) wifi: start max timer
I (3793) wifi: scan end: arg=0x0, status=0, ss_state=0x3
I (3794) wifi: back home chan=<1,0>, current chan=<2,0>
I (3794) wifi: ht20 freq=2412, chan=1
I (3796) wifi: start scan timer
I (3829) wifi: oper_channel: arg=0x0 time=627390
I (3829) wifi: perform scan: ss_state=0x9, chan<3,0>, dur<100,150>
I (3829) wifi: change: chan<3,0>, dur<100,150>
I (3832) wifi: ht20 freq=2422, chan=3
I (3836) wifi: enter start op, arg=0x3ffb5878
I (3840) wifi: scan operation: state=0x3, chan<3,0>, arg=0x3ffb5878, status=0
I (3846) wifi: scan specific ssid=SISTEL CONVIDADO
I (3851) wifi: start min timer
I (3854) wifi: start max timer
I (3954) wifi: scan end: arg=0x0, status=0, ss_state=0x3
I (3954) wifi: back home chan=<1,0>, current chan=<3,0>
I (3954) wifi: ht20 freq=2412, chan=1
I (3956) wifi: start scan timer
I (3989) wifi: oper_channel: arg=0x0 time=787722
I (3989) wifi: perform scan: ss_state=0x9, chan<4,0>, dur<100,150>
I (3989) wifi: change: chan<4,0>, dur<100,150>
I (3992) wifi: ht20 freq=2427, chan=4
I (3996) wifi: enter start op, arg=0x3ffb5878
I (4000) wifi: scan operation: state=0x3, chan<4,0>, arg=0x3ffb5878, status=0
I (4007) wifi: scan specific ssid=SISTEL CONVIDADO
I (4011) wifi: start min timer
I (4014) wifi: start max timer
I (4114) wifi: scan end: arg=0x0, status=0, ss_state=0x3
I (4114) wifi: back home chan=<1,0>, current chan=<4,0>
I (4114) wifi: ht20 freq=2412, chan=1
I (4117) wifi: start scan timer
I (4150) wifi: oper_channel: arg=0x0 time=948243
I (4150) wifi: perform scan: ss_state=0x9, chan<5,0>, dur<100,150>
I (4150) wifi: change: chan<5,0>, dur<100,150>
I (4153) wifi: ht20 freq=2432, chan=5
I (4157) wifi: enter start op, arg=0x3ffb5878
I (4160) wifi: scan operation: state=0x3, chan<5,0>, arg=0x3ffb5878, status=0
I (4167) wifi: scan specific ssid=SISTEL CONVIDADO
I (4172) wifi: start min timer
I (4175) wifi: start max timer
I (4275) wifi: scan end: arg=0x0, status=0, ss_state=0x3
I (4275) wifi: back home chan=<1,0>, current chan=<5,0>
I (4275) wifi: ht20 freq=2412, chan=1
I (4277) wifi: start scan timer
I (4310) wifi: oper_channel: arg=0x0 time=1108530
I (4310) wifi: perform scan: ss_state=0x9, chan<6,0>, dur<100,150>
I (4310) wifi: change: chan<6,0>, dur<100,150>
I (4313) wifi: ht20 freq=2437, chan=6
I (4317) wifi: enter start op, arg=0x3ffb5878
I (4321) wifi: scan operation: state=0x3, chan<6,0>, arg=0x3ffb5878, status=0
I (4328) wifi: scan specific ssid=SISTEL CONVIDADO
I (4332) wifi: start min timer
I (4335) wifi: start max timer
I (4435) wifi: scan end: arg=0x0, status=0, ss_state=0x3
I (4435) wifi: back home chan=<1,0>, current chan=<6,0>
I (4435) wifi: ht20 freq=2412, chan=1
I (4438) wifi: start scan timer
I (4470) wifi: oper_channel: arg=0x0 time=1268908
I (4470) wifi: perform scan: ss_state=0x9, chan<7,0>, dur<100,150>
I (4470) wifi: change: chan<7,0>, dur<100,150>
I (4474) wifi: ht20 freq=2442, chan=7
I (4477) wifi: enter start op, arg=0x3ffb5878
I (4481) wifi: scan operation: state=0x3, chan<7,0>, arg=0x3ffb5878, status=0
I (4488) wifi: scan specific ssid=SISTEL CONVIDADO
I (4493) wifi: start min timer
I (4495) wifi: start max timer
I (4595) wifi: scan end: arg=0x0, status=0, ss_state=0x3
I (4595) wifi: back home chan=<1,0>, current chan=<7,0>
I (4596) wifi: ht20 freq=2412, chan=1
I (4598) wifi: start scan timer
I (4631) wifi: oper_channel: arg=0x0 time=1429287
I (4631) wifi: perform scan: ss_state=0x9, chan<8,0>, dur<100,150>
I (4631) wifi: change: chan<8,0>, dur<100,150>
I (4634) wifi: ht20 freq=2447, chan=8
I (4638) wifi: enter start op, arg=0x3ffb5878
I (4642) wifi: scan operation: state=0x3, chan<8,0>, arg=0x3ffb5878, status=0
I (4648) wifi: scan specific ssid=SISTEL CONVIDADO
I (4653) wifi: start min timer
I (4656) wifi: start max timer
I (4756) wifi: scan end: arg=0x0, status=0, ss_state=0x3
I (4756) wifi: back home chan=<1,0>, current chan=<8,0>
I (4756) wifi: ht20 freq=2412, chan=1
I (4758) wifi: start scan timer
I (4791) wifi: oper_channel: arg=0x0 time=1589684
I (4791) wifi: perform scan: ss_state=0x9, chan<9,0>, dur<100,150>
I (4791) wifi: change: chan<9,0>, dur<100,150>
I (4794) wifi: ht20 freq=2452, chan=9
I (4798) wifi: enter start op, arg=0x3ffb5878
I (4802) wifi: scan operation: state=0x3, chan<9,0>, arg=0x3ffb5878, status=0
I (4809) wifi: scan specific ssid=SISTEL CONVIDADO
I (4813) wifi: start min timer
I (4816) wifi: start max timer
I (4916) wifi: scan end: arg=0x0, status=0, ss_state=0x3
I (4916) wifi: back home chan=<1,0>, current chan=<9,0>
I (4916) wifi: ht20 freq=2412, chan=1
I (4919) wifi: start scan timer
I (4951) wifi: oper_channel: arg=0x0 time=1750074
I (4952) wifi: perform scan: ss_state=0x9, chan<10,0>, dur<100,150>
I (4952) wifi: change: chan<10,0>, dur<100,150>
I (4955) wifi: ht20 freq=2457, chan=10
I (4959) wifi: enter start op, arg=0x3ffb5878
I (4963) wifi: scan operation: state=0x3, chan<10,0>, arg=0x3ffb5878, status=0
I (4970) wifi: scan specific ssid=SISTEL CONVIDADO
I (4974) wifi: start min timer
I (4977) wifi: start max timer
I (4984) wifi: profile match: ss_state=0x7
I (4984) wifi: scan histroy table is not full yet, add
I (4988) wifi: add ssid=SISTEL CONVIDADO, chan=11 to scan history
I (5023) wifi: profile match: ss_state=0x7
I (5023) wifi: update scan history ssid=SISTEL CONVIDADO, channel=11
I (5126) wifi: profile match: ss_state=0x7
I (5126) wifi: update scan history ssid=SISTEL CONVIDADO, channel=11
I (5130) wifi: scan end: arg=0x0, status=0, ss_state=0x7
I (5130) wifi: find first mathched ssid, scan done
I (5134) wifi: back home chan=<1,0>, current chan=<10,0>
I (5139) wifi: ht20 freq=2412, chan=1
I (5143) wifi: filter: set rx policy=4
I (5146) wifi: first chan=1
I (5148) wifi: scan_done: arg=0x0, status=0, cur_time=1947153, scan_id=128, scan state=0
I (5156) wifi: call scan_done cb, arg=0x0
I (5160) wifi: handoff_cb: status=0
I (5163) wifi: best bss has set.
I (5166) wifi: ap found, mac=8a:8a:20:f1:62:51
I (5170) wifi: bssid=8a:8a:20:f1:62:51, LR=0
I (5174) wifi: new_bss=0x3ffb39b0, cur_bss=0x0, new_chan=<11,0>, cur_chan=1
I (5181) wifi: filter: set rx policy=5
I (5184) wifi: ap channel adjust o:1,1 n:11,2
I (5189) wifi: new:<11,0>, old:<1,0>, ap:<11,2>, sta:<11,0>, prof:1
I (5195) wifi: ht20 freq=2462, chan=11
I (5198) wifi: connect_op: status=0, auth=5, cipher=3 
I (5203) wifi: auth mode is not none
I (5772) wifi: connect_bss: auth=1, reconnect=0
I (5772) wifi: state: init -> auth (b0)
I (5772) wifi: start 1s AUTH timer
I (5772) wifi: clear scan ap list
I (5779) wifi: recv auth: seq=2, status=0
I (5780) wifi: state: auth -> assoc (0)
I (5782) wifi: restart connect 1s timer for assoc
I (5794) wifi: recv assoc: type=0x10
I (5794) wifi: filter: set rx policy=6
I (5794) wifi: state: assoc -> run (10)
I (5797) wifi: start 10s connect timer for 4 way handshake
I (5802) wifi: wpa_psk start
I (5805) wifi: wpa_psk handle succeed
I (5813) wifi: wpa_psk start
I (5814) wifi: wpa_psk handle succeed
I (5816) wifi: connected with SISTEL CONVIDADO, channel 11, bssid = 8a:8a:20:f1:62:51
I (5821) wifi: remove all except 8a:8a:20:f1:62:51 from rc list
I (5827) wifi: clear blacklist
I (5830) wifi: filter: set rx policy=7
I (5833) wifi: pm start, type: 1

I (5837) wifi: Send sta connected event
I (5840) wifi: connect status 1 -> 5, step=1, err_time=0
I (8920) event: sta ip: 192.168.5.78, mask: 255.255.255.0, gw: 192.168.5.1
2. Here, ESP32 can't connect to AP

Code: Select all

I (3310) wifi: mode : sta (3c:71:bf:6e:a9:fc) + softAP (3c:71:bf:6e:a9:fd)
I (3317) wifi: filter: set rx policy=9
I (3320) wifi: ht20 freq=2412, chan=1
I (3327) wifi: Start wifi disconnect
I (3327) wifi: connect step 0 -> 0, status=0, err_time=0
I (3332) wifi: connect status 0 -> 0, step=0, err_time=0
I (3337) wifi: filter: set rx policy=8
I (3340) wifi: clear blacklist
I (3343) wifi: Start wifi connect
I (3346) wifi: connect step 0 -> 0, status=0, err_time=0
I (3351) wifi: connect chan=0
I (3354) wifi: nvs=0, ssid=SISTEL CONVIDADO, channel=255
I (3359) wifi: ssid=SISTEL CONVIDADO match nvs 0, channel=255
I (3364) wifi: first chan=1
I (3367) wifi: connect status 0 -> 1, step=0, err_time=0
I (3372) wifi: connect step 0 -> 1, status=1, err_time=0
I (3377) wifi: filter: set rx policy=3
I (3380) wifi: clear scan ap list
I (3383) wifi: start scan: type=0x50f, priority=2, cb=0x40126b98, arg=0x0, ss_state=0x1, time=239534, index=0
0x40126b98: cnx_start_handoff_cb at ??:?

I (3393) wifi: inter_channel_timeout: arg=0x0, ss_state=0x1
I (3398) wifi: perform scan: ss_state=0x9, chan<1,0>, dur<100,150>
I (3404) wifi: change: chan<1,0>, dur<100,150>
I (3408) wifi: enter start op, arg=0x3ffb5878
I (3412) wifi: scan operation: state=0x3, chan<1,0>, arg=0x3ffb5878, status=0
I (3419) wifi: scan specific ssid=SISTEL CONVIDADO
I (3424) wifi: start min timer
I (3427) wifi: start max timer
I (3461) wifi: profile match: ss_state=0x7
I (3461) wifi: scan histroy table is not full yet, add
I (3461) wifi: add ssid=SISTEL CONVIDADO, chan=1 to scan history
I (3563) wifi: profile match: ss_state=0x7
I (3563) wifi: update scan history ssid=SISTEL CONVIDADO, channel=1
I (3579) wifi: scan end: arg=0x0, status=0, ss_state=0x7
I (3580) wifi: find first mathched ssid, scan done
I (3580) wifi: back home chan=<1,0>, current chan=<1,0>
I (3583) wifi: filter: set rx policy=4
I (3586) wifi: first chan=1
I (3589) wifi: scan_done: arg=0x0, status=0, cur_time=445029, scan_id=128, scan state=0
I (3597) wifi: call scan_done cb, arg=0x0
I (3600) wifi: handoff_cb: status=0
I (3604) wifi: best bss has set.
I (3607) wifi: ap found, mac=0e:ec:da:b4:03:70
I (3611) wifi: bssid=0e:ec:da:b4:03:70, LR=0
I (3615) wifi: new_bss=0x3ffb39b0, cur_bss=0x0, new_chan=<1,0>, cur_chan=1
I (3621) wifi: filter: set rx policy=5
I (3625) wifi: sta/ap in the same channel, but ap is ht40, use ht40
I (3631) wifi: new:<1,1>, old:<1,0>, ap:<1,1>, sta:<1,0>, prof:1
I (3636) wifi: ht40u freq=2422, chan=1
I (3640) wifi: connect_op: status=0, auth=5, cipher=3 
I (3645) wifi: auth mode is not none
I (4214) wifi: connect_bss: auth=1, reconnect=0
I (4214) wifi: state: init -> auth (b0)
I (4214) wifi: start 1s AUTH timer
I (4214) wifi: clear scan ap list
I (5214) wifi: auth timeout
I (5215) wifi: state: auth -> init (200)
I (5215) wifi: connect step 1 -> 4, status=1, err_time=1
I (5215) wifi: stop beacon/connect timer
I (5218) wifi: reason: auth expire(2)
I (5222) wifi: add bssid 0e:ec:da:b4:03:70 to blacklist, cnt=0
I (5227) wifi: stop CSA timer
I (5230) wifi: remove 0e:ec:da:b4:03:70 from rc list
I (5235) wifi: new:<1,0>, old:<1,1>, ap:<1,1>, sta:<1,0>, prof:1
I (5240) wifi: ht20 freq=2412, chan=1
I (5244) wifi: filter: set rx policy=8
I (5247) wifi: Send disconnect event, reason=2, AP number=0

//Fail to connect in WiFi (over 40seg)
3. Here, ESP32 can connect to WiFi but can't get IP DHCP.

Code: Select all

I (3351) wifi: mode : sta (3c:71:bf:6e:a9:fc) + softAP (3c:71:bf:6e:a9:fd)
I (3358) wifi: filter: set rx policy=9
I (3361) wifi: ht20 freq=2412, chan=1
I (3368) wifi: Start wifi disconnect
I (3368) wifi: connect step 0 -> 0, status=0, err_time=0
I (3373) wifi: connect status 0 -> 0, step=0, err_time=0
I (3378) wifi: filter: set rx policy=8
I (3381) wifi: clear blacklist
I (3384) wifi: Start wifi connect
I (3387) wifi: connect step 0 -> 0, status=0, err_time=0
I (3392) wifi: connect chan=0
I (3395) wifi: nvs=0, ssid=SISTEL CONVIDADO, channel=255
I (3400) wifi: ssid=SISTEL CONVIDADO match nvs 0, channel=255
I (3405) wifi: first chan=1
I (3408) wifi: connect status 0 -> 1, step=0, err_time=0
I (3413) wifi: connect step 0 -> 1, status=1, err_time=0
I (3418) wifi: filter: set rx policy=3
I (3421) wifi: clear scan ap list
I (3424) wifi: start scan: type=0x50f, priority=2, cb=0x40126b98, arg=0x0, ss_state=0x1, time=239086, index=0
0x40126b98: cnx_start_handoff_cb at ??:?

I (3434) wifi: inter_channel_timeout: arg=0x0, ss_state=0x1
I (3439) wifi: perform scan: ss_state=0x9, chan<1,0>, dur<100,150>
I (3445) wifi: change: chan<1,0>, dur<100,150>
I (3449) wifi: enter start op, arg=0x3ffb5878
I (3453) wifi: scan operation: state=0x3, chan<1,0>, arg=0x3ffb5878, status=0
I (3460) wifi: scan specific ssid=SISTEL CONVIDADO
I (3465) wifi: start min timer
I (3468) wifi: start max timer
I (3477) wifi: profile match: ss_state=0x7
I (3478) wifi: scan histroy table is not full yet, add
I (3479) wifi: add ssid=SISTEL CONVIDADO, chan=1 to scan history
I (3485) wifi: profile match: ss_state=0x7
I (3489) wifi: update scan history ssid=SISTEL CONVIDADO, channel=1
I (3579) wifi: profile match: ss_state=0x7
I (3580) wifi: update scan history ssid=SISTEL CONVIDADO, channel=1
I (3620) wifi: scan end: arg=0x0, status=0, ss_state=0x7
I (3621) wifi: find first mathched ssid, scan done
I (3621) wifi: back home chan=<1,0>, current chan=<1,0>
I (3624) wifi: filter: set rx policy=4
I (3627) wifi: first chan=1
I (3630) wifi: scan_done: arg=0x0, status=0, cur_time=444622, scan_id=128, scan state=0
I (3638) wifi: call scan_done cb, arg=0x0
I (3641) wifi: handoff_cb: status=0
I (3645) wifi: best bss has set.
I (3648) wifi: ap found, mac=0e:ec:da:b4:03:70
I (3652) wifi: bssid=0e:ec:da:b4:03:70, LR=0
I (3656) wifi: new_bss=0x3ffb39b0, cur_bss=0x0, new_chan=<1,0>, cur_chan=1
I (3662) wifi: filter: set rx policy=5
I (3666) wifi: sta/ap in the same channel, but ap is ht40, use ht40
I (3672) wifi: new:<1,1>, old:<1,0>, ap:<1,1>, sta:<1,0>, prof:1
I (3678) wifi: ht40u freq=2422, chan=1
I (3681) wifi: connect_op: status=0, auth=5, cipher=3 
I (3686) wifi: auth mode is not none
I (4255) wifi: connect_bss: auth=1, reconnect=0
I (4255) wifi: state: init -> auth (b0)
I (4255) wifi: start 1s AUTH timer
I (4255) wifi: clear scan ap list
I (4264) wifi: recv auth: seq=2, status=0
I (4264) wifi: state: auth -> assoc (0)
I (4265) wifi: restart connect 1s timer for assoc
I (4270) wifi: recv auth: seq=2, status=0
I (4273) wifi: not auth state, ignore
I (4278) wifi: recv assoc: type=0x10
I (4280) wifi: filter: set rx policy=6
I (4283) wifi: state: assoc -> run (10)
I (4287) wifi: start 10s connect timer for 4 way handshake
I (4292) wifi: wpa_psk start
I (4295) wifi: wpa_psk handle succeed
I (4326) wifi: wpa_psk start
I (4327) wifi: wpa_psk handle succeed
I (4331) wifi: connected with SISTEL CONVIDADO, channel 1, bssid = 0e:ec:da:b4:03:70
I (4331) wifi: remove all except 0e:ec:da:b4:03:70 from rc list
I (4334) wifi: clear blacklist
I (4337) wifi: filter: set rx policy=7
I (4340) wifi: pm start, type: 1

I (4343) wifi: Send sta connected event
I (4347) wifi: connect status 1 -> 5, step=1, err_time=0

//Fail to get IP DHCP (over 40seg)

User avatar
urbanze
Posts: 267
Joined: Sat Jun 10, 2017 9:55 pm
Location: Brazil

Re: WiFi STA fail to connect in enterprise AP.

Postby urbanze » Thu Jul 16, 2020 10:53 pm

Any ideia? This make no sense to me. I've seen other reports of this type and I think the problem is in enterprise WiFi, but how to solve it? What can I do?

axellin
Posts: 71
Joined: Mon Sep 17, 2018 9:09 am

Re: WiFi STA fail to connect in enterprise AP.

Postby axellin » Fri Jul 17, 2020 12:38 am

You probably need to report this issue on github with your IDF version/FreeRadius version and setup settings.
(In my test, the enterprise AP does not work with freeradius 3.0.20)
It's useful if you also provide the RADIUS log messages.

Who is online

Users browsing this forum: No registered users and 31 guests