Failing to Assign IP when joining AP - HomeKit (IDFGH-5687) (IDFGH-5715)

codspeed commented 3 years ago

Environment

Module or chip used: ESP32-WROOM-32D
IDF version (run git describe --tags to find it): v4.3
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: macOS
Using an IDE?: VCode
Power Supply: USB/external 3.3V

Problem Description

For our RM + HK setup and custom application based of HomeKit_Switch On many occasions we are finding that when we join the device in WAC mode using the Home app that it does not assign an IP or Start the Pair Setup. Very often on the first attempt after a reboot. Please see example where it took 4 attempts to successfully initiate.

Expected Behavior

IP Assigned and device begins the Pair Setup immediately.

Actual Behavior

No IP Assigned or Paring Started

Steps to reproduce

Device should be in WAC mode
Home App -> Add Accessory -> Tap the Device

Debug Logs

I (1823) EVENT_HANDLER: HAP_WAC_EVENT_REQ_SOFTAP_START
I (1823) ap_prcs: isWAC: 0
I (1823) ap_prcs: Attempt to set state(1): 0x01
I (1833) ap_prcs: Attempt to set state(2): 0x01
I (1843) ap_prcs: SetStateRegister 1
I (7853) wifi:new:<1,0>, old:<1,1>, ap:<1,1>, sta:<0,0>, prof:1
I (7863) wifi:station: 8e:43:3c:7a:7c:59 join, AID=1, bgn, 20
I (22233) wifi:station: 8e:43:3c:7a:7c:59 leave, AID = 1, bss_flags is 134259, bss:0x3ffe15d0
I (22233) wifi:new:<1,0>, old:<1,0>, ap:<1,1>, sta:<0,0>, prof:1
I (30593) wifi:new:<1,0>, old:<1,0>, ap:<1,1>, sta:<0,0>, prof:1
I (30593) wifi:station: 8e:43:3c:7a:7c:59 join, AID=1, bgn, 20
W (31243) wifi:Haven't to connect to a suitable AP now!
I (47763) wifi:station: 8e:43:3c:7a:7c:59 leave, AID = 1, bss_flags is 134259, bss:0x3ffe15d0
I (47763) wifi:new:<1,0>, old:<1,0>, ap:<1,1>, sta:<0,0>, prof:1
W (61243) wifi:Haven't to connect to a suitable AP now!
I (72353) wifi:new:<1,0>, old:<1,0>, ap:<1,1>, sta:<0,0>, prof:1
I (72353) wifi:station: 8e:43:3c:7a:7c:59 join, AID=1, bgn, 20
I (88523) wifi:station: 8e:43:3c:7a:7c:59 leave, AID = 1, bss_flags is 134259, bss:0x3ffe15d0
I (88523) wifi:new:<1,0>, old:<1,0>, ap:<1,1>, sta:<0,0>, prof:1
W (91243) wifi:Haven't to connect to a suitable AP now!
I (99573) wifi:new:<1,0>, old:<1,0>, ap:<1,1>, sta:<0,0>, prof:1
I (99583) wifi:station: 8e:43:3c:7a:7c:59 join, AID=1, bgn, 20
I (102363) esp_netif_lwip: DHCP server assigned IP to a station, IP is: 192.168.4.2
I (102363) EVENT_HANDLER: IP_EVENT_AP_STAIPASSIGNED
W (104253) wifi:<ba-add>idx:4 (ifx:1, 8e:43:3c:7a:7c:59), tid:0, ssn:0, winSize:64
######## Starting Pair Setup ########
Pair Setup M1 Received
Pair Setup M2 Successful
I (104763) EVENT_HANDLER: Pairing Started

Thanks.

codspeed commented 3 years ago

With debug logs enabled. First attempt fails, second succeeds.

`D (5334) EVENT_HANDLER: app_homekit_event_handler: event_base HAP_WAC_EVENT event_id 3 I (5334) EVENT_HANDLER: HAP_WAC_EVENT_REQ_SOFTAP_START I (5344) ap_prcs: isWAC: 0 I (5344) ap_prcs: Attempt to set state(1): 0x01 I (5354) ap_prcs: Attempt to set state(2): 0x01 I (5354) ap_prcs: SetStateRegister 1 D (5364) event: running post HAP_WAC_EVENT:3 with handler 0x400ee22c and context 0x3ffdcfcc on loop 0x3ffc0484 0x400ee22c: ble_gap_master_connect_cancelled at /Users/user/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_gap.c:872

D (5374) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x3ffdb35c D (5384) httpd_uri: httpd_find_uri_handler: [0] = /pair-setup D (5384) httpd_uri: httpd_find_uri_handler: [1] = /pair-verify D (5394) httpd_uri: httpd_find_uri_handler: [2] = /pairings D (5394) httpd_uri: httpd_find_uri_handler: [3] = /accessories D (5404) httpd_uri: httpd_find_uri_handler: [4] = /characteristics D (5404) httpd_uri: httpd_find_uri_handler: [5] = /characteristics D (5414) httpd_uri: httpd_find_uri_handler: [6] = /identify D (5424) httpd_uri: httpd_find_uri_handler: [7] = /prepare D (5424) httpd_uri: httpd_find_uri_handler: [8] = /proto-ver D (5434) httpd_uri: httpd_find_uri_handler: [9] = /prov-session D (5434) httpd_uri: httpd_find_uri_handler: [10] = /prov-config D (5444) httpd_uri: httpd_find_uri_handler: [11] = /prov-scan D (5454) httpd_uri: httpd_find_uri_handler: [12] = /cloud_user_assoc D (5454) httpd_uri: httpd_register_uri_handler: [0] exists /pair-setup D (5464) httpd_uri: httpd_register_uri_handler: [1] exists /pair-verify D (5474) httpd_uri: httpd_register_uri_handler: [2] exists /pairings D (5474) httpd_uri: httpd_register_uri_handler: [3] exists /accessories D (5484) httpd_uri: httpd_register_uri_handler: [4] exists /characteristics D (5494) httpd_uri: httpd_register_uri_handler: [5] exists /characteristics D (5494) httpd_uri: httpd_register_uri_handler: [6] exists /identify D (5504) httpd_uri: httpd_register_uri_handler: [7] exists /prepare D (5514) httpd_uri: httpd_register_uri_handler: [8] exists /proto-ver D (5514) httpd_uri: httpd_register_uri_handler: [9] exists /prov-session D (5524) httpd_uri: httpd_register_uri_handler: [10] exists /prov-config D (5534) httpd_uri: httpd_register_uri_handler: [11] exists /prov-scan D (5534) httpd_uri: httpd_register_uri_handler: [12] exists /cloud_user_assoc D (5544) httpd_uri: httpd_register_uri_handler: [13] installed /config D (5554) httpd_uri: httpd_find_uri_handler: [0] = /pair-setup D (5554) httpd_uri: httpd_find_uri_handler: [1] = /pair-verify D (5564) httpd_uri: httpd_find_uri_handler: [2] = /pairings D (5564) httpd_uri: httpd_find_uri_handler: [3] = /accessories D (5574) httpd_uri: httpd_find_uri_handler: [4] = /characteristics D (5584) httpd_uri: httpd_find_uri_handler: [5] = /characteristics D (5584) httpd_uri: httpd_find_uri_handler: [6] = /identify D (5594) httpd_uri: httpd_find_uri_handler: [7] = /prepare D (5594) httpd_uri: httpd_find_uri_handler: [8] = /proto-ver D (5604) httpd_uri: httpd_find_uri_handler: [9] = /prov-session D (5604) httpd_uri: httpd_find_uri_handler: [10] = /prov-config D (5614) httpd_uri: httpd_find_uri_handler: [11] = /prov-scan D (5624) httpd_uri: httpd_find_uri_handler: [12] = /cloud_user_assoc D (5624) httpd_uri: httpd_find_uri_handler: [13] = /config D (5634) httpd_uri: httpd_register_uri_handler: [0] exists /pair-setup D (5634) httpd_uri: httpd_register_uri_handler: [1] exists /pair-verify D (5644) httpd_uri: httpd_register_uri_handler: [2] exists /pairings D (5654) httpd_uri: httpd_register_uri_handler: [3] exists /accessories D (5654) httpd_uri: httpd_register_uri_handler: [4] exists /characteristics D (5664) httpd_uri: httpd_register_uri_handler: [5] exists /characteristics D (5674) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x3ffdb35c D (5684) httpd_uri: httpd_register_uri_handler: [6] exists /identify D (5684) httpd_uri: httpd_register_uri_handler: [7] exists /prepare D (5694) httpd_uri: httpd_register_uri_handler: [8] exists /proto-ver D (5694) httpd_uri: httpd_register_uri_handler: [9] exists /prov-session D (5704) httpd_uri: httpd_register_uri_handler: [10] exists /prov-config D (5714) httpd_uri: httpd_register_uri_handler: [11] exists /prov-scan D (5714) httpd_uri: httpd_register_uri_handler: [12] exists /cloud_user_assoc D (5724) httpd_uri: httpd_register_uri_handler: [13] exists /config D (5734) httpd_uri: httpd_register_uri_handler: [14] installed /configured D (5744) event: running post HAP_WAC_EVENT:0 with handler 0x400ee22c and context 0x3ffdcfcc on loop 0x3ffc0484 0x400ee22c: ble_gap_master_connect_cancelled at /Users/user/TEST/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_gap.c:872

D (6774) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x3ffdb35c D (7874) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x3ffdb35c W (32514) wifi:Haven't to connect to a suitable AP now! I (52684) wifi:new:<1,0>, old:<1,1>, ap:<1,1>, sta:<0,0>, prof:1 I (52684) wifi:station: 7a:91:1b:46:42:b3 join, AID=1, bgn, 20 D (52684) event: running post WIFI_EVENT:14 with handler 0x400ee22c and context 0x3ffc675c on loop 0x3ffc0484 0x400ee22c: ble_gap_master_connect_cancelled at /Users/user/TEST/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_gap.c:872

D (52694) event: running post WIFI_EVENT:14 with handler 0x4010e26c and context 0x3ffd02bc on loop 0x3ffc0484 0x4010e26c: protobuf_c_message_unpack at ??:?

D (52704) event: running post WIFI_EVENT:14 with handler 0x4010e374 and context 0x3ffd14e4 on loop 0x3ffc0484 0x4010e374: protobuf_c_message_unpack at ??:?

D (52714) event: running post WIFI_EVENT:14 with handler 0x4011e250 and context 0x3ffd9b58 on loop 0x3ffc0484 0x4011e250: crypto_sign_ed25519_keypair at /Users/user/TEST/esp-idf/components/libsodium/libsodium/src/libsodium/crypto_sign/ed25519/ref10/keypair.c:39

D (52724) event: running post WIFI_EVENT:14 with handler 0x4011684c and context 0x3ffdcbf0 on loop 0x3ffc0484 0x4011684c: hap_process_pair_add at /Users/user/TEST/esp-homekit-sdk/components/homekit/esp_hap_core/src/esp_hap_pairings.c:129

D (52924) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x3ffdb35c W (62514) wifi:Haven't to connect to a suitable AP now! I (80754) wifi:station: 7a:91:1b:46:42:b3 leave, AID = 1, bss_flags is 134243, bss:0x3ffdd8f0 I (80754) wifi:new:<1,0>, old:<1,0>, ap:<1,1>, sta:<0,0>, prof:1 D (80764) event: running post WIFI_EVENT:15 with handler 0x400ee22c and context 0x3ffc675c on loop 0x3ffc0484 0x400ee22c: ble_gap_master_connect_cancelled at /Users/user/TEST/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_gap.c:872

D (80774) event: running post WIFI_EVENT:15 with handler 0x4010e26c and context 0x3ffd02bc on loop 0x3ffc0484 0x4010e26c: protobuf_c_message_unpack at ??:?

D (80784) event: running post WIFI_EVENT:15 with handler 0x4010e374 and context 0x3ffd14e4 on loop 0x3ffc0484 0x4010e374: protobuf_c_message_unpack at ??:?

D (80794) event: running post WIFI_EVENT:15 with handler 0x4011e250 and context 0x3ffd9b58 on loop 0x3ffc0484 0x4011e250: crypto_sign_ed25519_keypair at /Users/user/TEST/esp-idf/components/libsodium/libsodium/src/libsodium/crypto_sign/ed25519/ref10/keypair.c:39

D (80804) event: running post WIFI_EVENT:15 with handler 0x4011684c and context 0x3ffdcbf0 on loop 0x3ffc0484 0x4011684c: hap_process_pair_add at /Users/user/TEST/esp-homekit-sdk/components/homekit/esp_hap_core/src/esp_hap_pairings.c:129

W (92514) wifi:Haven't to connect to a suitable AP now! I (98524) wifi:new:<1,0>, old:<1,0>, ap:<1,1>, sta:<0,0>, prof:1 I (98524) wifi:station: 7a:91:1b:46:42:b3 join, AID=1, bgn, 20 D (98524) event: running post WIFI_EVENT:14 with handler 0x400ee22c and context 0x3ffc675c on loop 0x3ffc0484 0x400ee22c: ble_gap_master_connect_cancelled at /Users/user/TEST/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_gap.c:872

D (98534) event: running post WIFI_EVENT:14 with handler 0x4010e26c and context 0x3ffd02bc on loop 0x3ffc0484 0x4010e26c: protobuf_c_message_unpack at ??:?

D (98544) event: running post WIFI_EVENT:14 with handler 0x4010e374 and context 0x3ffd14e4 on loop 0x3ffc0484 0x4010e374: protobuf_c_message_unpack at ??:?

D (98554) event: running post WIFI_EVENT:14 with handler 0x4011e250 and context 0x3ffd9b58 on loop 0x3ffc0484 0x4011e250: crypto_sign_ed25519_keypair at /Users/user/TEST/esp-idf/components/libsodium/libsodium/src/libsodium/crypto_sign/ed25519/ref10/keypair.c:39

D (98564) event: running post WIFI_EVENT:14 with handler 0x4011684c and context 0x3ffdcbf0 on loop 0x3ffc0484 0x4011684c: hap_process_pair_add at /Users/user/TEST/esp-homekit-sdk/components/homekit/esp_hap_core/src/esp_hap_pairings.c:129

D (98674) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x3ffdb35c D (100294) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x3ffdb35c D (101324) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x3ffdb35c I (101324) esp_netif_lwip: DHCP server assigned IP to a station, IP is: 192.168.4.2 D (101334) event: running post IP_EVENT:2 with handler 0x4010e374 and context 0x3ffd173c on loop 0x3ffc0484 0x4010e374: protobuf_c_message_unpack at ??:?

D (101344) event: running post IP_EVENT:2 with handler 0x400e5c00 and context 0x3ffd3f1c on loop 0x3ffc0484 0x400e5c00: wifi_prov_mgr_set_app_info at /Users/user/TEST/esp-idf/components/wifi_provisioning/src/manager.c:234

D (101354) EVENT_HANDLER: app_homekit_event_handler: event_base IP_EVENT event_id 2 I (101364) EVENT_HANDLER: IP_EVENT_AP_STAIPASSIGNED D (101364) event: running post IP_EVENT:2 with handler 0x4011e250 and context 0x3ffd9b8c on loop 0x3ffc0484 0x4011e250: crypto_sign_ed25519_keypair at /Users/user/TEST/esp-idf/components/libsodium/libsodium/src/libsodium/crypto_sign/ed25519/ref10/keypair.c:39

W (103214) wifi:idx:4 (ifx:1, 7a:91:1b:46:42:b3), tid:0, ssn:0, winSize:64 D (103274) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x3ffdb35c D (103494) httpd: httpd_server: processing listen socket 48 D (103494) httpd: httpd_accept_conn: newfd = 51 D (103494) httpd_sess: httpd_sess_new: fd = 51 D (103504) httpd: httpd_accept_conn: complete D (103504) httpd: httpd_server: doing select maxfd+1 = 52 D (103514) httpd: httpd_server: processing socket 51 D (103514) httpd_sess: httpd_sess_process: httpd_req_new D (103524) httpd_txrx: httpd_recv_with_opt: requested length = 128 D (103524) httpd_txrx: httpd_recv_with_opt: received length = 94 D (103534) httpd_parse: read_block: received HTTP request block size = 94 D (103544) httpd_parse: cb_url: message begin D (103544) httpd_parse: cb_url: processing url = /pair-setup D (103554) httpd_parse: verify_url: received URI = /pair-setup D (103554) httpd_parse: cb_header_field: headers begin D (103564) httpd_txrx: httpd_unrecv: length = 67 D (103564) httpd_parse: pause_parsing: paused D (103574) httpd_parse: cb_header_field: processing field = Content-Length D (103574) httpd_txrx: httpd_recv_with_opt: requested length = 128 D (103584) httpd_txrx: httpd_recv_with_opt: pending length = 67 D (103594) httpd_parse: read_block: received HTTP request block size = 67 D (103594) httpd_parse: continue_parsing: skip pre-parsed data of size = 15 D (103604) httpd_parse: continue_parsing: un-paused D (103604) httpd_parse: cb_header_value: processing value = 6 D (103614) httpd_parse: cb_header_field: processing field = Content-Type D (103624) httpd_parse: cb_header_value: processing value = application/pairing+tlv8 D (103624) httpd_parse: cb_headers_complete: bytes read = 88 D (103634) httpd_parse: cb_headers_complete: content length = 6 D (103644) httpd_txrx: httpd_unrecv: length = 6 D (103644) httpd_parse: pause_parsing: paused D (103654) httpd_parse: cb_on_body: body begins D (103654) httpd_parse: httpd_parse_req: parsing complete D (103664) httpd_uri: httpd_uri: request for /pair-setup with type 3 D (103664) httpd_uri: httpd_find_uri_handler: [0] = /pair-setup ######## Starting Pair Setup ######## D (103674) httpd_txrx: httpd_req_recv: remaining length = 6 D (103684) httpd_txrx: httpd_recv_with_opt: requested length = 6 D (103684) httpd_txrx: httpd_recv_with_opt: pending length = 6 D (103694) httpd_txrx: httpd_req_recv: received length = 6 Pair Setup M1 Received Pair Setup M2 Successful D (103844) event: running post HAP_EVENT:5 with handler 0x400e5c00 and context 0x3ffd40e0 on loop 0x3ffc0484 0x400e5c00: wifi_prov_mgr_set_app_info at /Users/user/TEST/esp-idf/components/wifi_provisioning/src/manager.c:234

D (103844) EVENT_HANDLER: app_homekit_event_handler: event_base HAP_EVENT event_id 5 I (103854) EVENT_HANDLER: Pairing Started D (103864) httpd_txrx: httpd_send_all: sent = 78 D (103864) httpd_txrx: httpd_send_all: sent = 2 D (103874) httpd_txrx: httpd_send_all: sent = 409 D (103874) httpd_sess: httpd_sess_process: httpd_req_delete D (103884) httpd_sess: httpd_sess_process: success D (103884) httpd: httpd_server: doing select maxfd+1 = 52 D (104064) httpd: httpd_server: processing socket 51 D (104064) httpd_sess: httpd_sess_process: httpd_req_new D (104064) httpd_txrx: httpd_recv_with_opt: requested length = 128 D (104074) httpd_txrx: httpd_recv_with_opt: received length = 128 D (104084) httpd_parse: read_block: received HTTP request block size = 128 D (104084) httpd_parse: cb_url: message begin D (104094) httpd_parse: cb_url: processing url = /pair-setup D (104094) httpd_parse: verify_url: received URI = /pair-setup D (104104) httpd_parse: cb_header_field: headers begin D (104104) httpd_txrx: httpd_unrecv: length = 101 D (104114) httpd_parse: pause_parsing: paused D (104114) httpd_parse: cb_header_field: processing field = Content-Length D (104124) httpd_txrx: httpd_recv_with_opt: requested length = 128 D (104134) httpd_txrx: httpd_recv_with_opt: pending length = 101 D (104134) httpd_parse: read_block: received HTTP request block size = 101 D (104144) httpd_parse: continue_parsing: skip pre-parsed data of size = 15 D (104154) httpd_parse: continue_parsing: un-paused D (104154) httpd_parse: cb_header_value: processing value = 457 D (104164) httpd_parse: cb_header_field: processing field = Content-Type D (104164) httpd_parse: cb_header_value: processing value = application/pairing+tlv8 D (104174) httpd_parse: cb_headers_complete: bytes read = 90 D (104184) httpd_parse: cb_headers_complete: content length = 457 D (104184) httpd_txrx: httpd_unrecv: length = 38 D (104194) httpd_parse: pause_parsing: paused D (104194) httpd_parse: cb_on_body: body begins D (104204) httpd_parse: httpd_parse_req: parsing complete D (104204) httpd_uri: httpd_uri: request for /pair-setup with type 3 D (104214) httpd_uri: httpd_find_uri_handler: [0] = /pair-setup D (104224) httpd_txrx: httpd_req_recv: remaining length = 457 D (104224) httpd_txrx: httpd_recv_with_opt: requested length = 457 D (104234) httpd_txrx: httpd_recv_with_opt: pending length = 38 D (104234) httpd_txrx: httpd_recv_with_opt: received length = 457 D (104244) httpd_txrx: httpd_req_recv: received length = 457 Pair Setup M3 Received`

xueyunfei998 commented 3 years ago

hi @codspeed The log in the middle shows how many times the AP failed to join

I (101324) esp_netif_lwip: DHCP server assigned IP to a station, IP is: 192.168.4.2

but, the IP address is finally obtained.

From the log, there is no reason. It may be necessary to capture packets to analyze this problem.

In addition, can I reproduce this problem locally?

codspeed commented 3 years ago

The log in the middle shows how many times the AP failed to join

Correct, this is multiple attempts of trying, then disconnecting and trying again manually each time.

From the log, there is no reason. It may be necessary to capture packets to analyze this problem.

How do you suggest we do this exactly? I will have it done and send the results.

In addition, can I reproduce this problem locally?

I am unsure, we would need to send you the binaries of the project.

xueyunfei998 commented 3 years ago

hi @codspeed Can you provide a code to reproduce the problem? I want to reproduce the problem locally

xueyunfei998 commented 2 years ago

hi @codspeed Does this problem still exist? If this problem still exists, please provide the next recurring demo and idf commit iD and router model.

Alvin1Zhang commented 2 years ago

Thanks for reporting, will close due to short of feedback, feel free to reopen with more updates, thanks.

espressif / esp-idf