search

espressif / esp-rainmaker

ESP RainMaker Agent for firmware development
Apache License 2.0
433 stars 146 forks source link

Provisioning always with connection problem and reconnecting to AP - long time wasted during provisioning (MEGH-3691) #148

Closed jacek12345 closed 1 year ago

jacek12345 commented 1 year ago

Using:

Provisioning always lasts a long time due to connection problem (look near "I (34571) wifi:bcn_timout,ap_probe_send_start" line):

I (1121) app_wifi: If QR code is not visible, copy paste the below URL in a browser.
https://rainmaker.espressif.com/qrcode.html?data={"ver":"v1","name":"PROV_b1e797","pop":"5c393564","transport":"ble"}
I (1141) app_main: Provisioning QR : {"ver":"v1","name":"PROV_b1e797","pop":"5c393564","transport":"ble"}
I (1151) app_wifi: Provisioning Started. Name : PROV_b1e797, POP : 5c393564
I (1161) app_wifi: Provisioning will auto stop after 30 minute(s).
I (10671) protocomm_nimble: mtu update event; conn_handle=1 cid=4 mtu=256

I (21651) esp_rmaker_user_mapping: Received request for node details
I (21651) esp_rmaker_user_mapping: Got user_id = SignInWithApple_txxxxxxxxxxxxxxxxxxxxxx, secret_key = xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx
I (21671) esp_rmaker_user_mapping: User Node mapping reset detected.
I (21671) esp_rmaker_user_mapping: Sending status SUCCESS
I (21931) app_wifi: Received Wi-Fi credentials
        SSID     : Jacek
        Password : xxxxxxxxxxx
I (25341) wifi:new:<11,0>, old:<1,0>, ap:<255,255>, sta:<11,0>, prof:1
I (25351) wifi:state: init -> auth (b0)
I (26021) wifi:state: auth -> assoc (0)
I (26031) wifi:state: assoc -> run (10)
I (26051) wifi:connected with Jacek, aid = 16, channel 11, BW20, bssid = e8:d2:ff:59:9c:a4
I (26051) wifi:security: WPA3-SAE, phy: bgn, rssi: -63
I (26061) wifi:pm start, type: 1

I (26061) wifi:set rx beacon pti, rx_bcn_pti: 14, bcn_timeout: 14, mt_pti: 25000, mt_time: 10000
I (26111) wifi:BcnInt:102400, DTIM:3
W (26111) wifi:<ba-add>idx:0 (ifx:0, e8:d2:ff:59:9c:a4), tid:0, ssn:1, winSize:64
I (27091) app_wifi: Connected with IP Address:192.168.1.63
I (27091) esp_netif_handlers: sta ip: 192.168.1.63, mask: 255.255.255.0, gw: 192.168.1.1
I (27091) wifi_prov_mgr: STA Got IP
I (27091) app_wifi: Provisioning successful
I (27101) esp_rmaker_local: Waiting for Wi-Fi provisioning to finish.
I (27111) esp_mqtt_glue: Connecting to a1p72mufdu6064-ats.iot.us-east-1.amazonaws.com
I (27111) esp_mqtt_glue: Waiting for MQTT connection. This may take time.
I (27571) esp-x509-crt-bundle: Certificate validated
I (28551) NimBLE: GAP procedure initiated: stop advertising.

I (28551) NimBLE: GAP procedure initiated: stop advertising.

I (28561) NimBLE: GAP procedure initiated: terminate connection; conn_handle=1 hci_reason=19

E (28611) protocomm_nimble: Error setting advertisement data; rc = 30
W (28631) Timer: Timer not stopped
W (28641) Timer: Timer not stopped
I (28661) wifi_prov_mgr: Provisioning stopped
W (28661) BTDM_INIT: esp_bt_mem_release not implemented, return OK
I (28671) wifi_prov_scheme_ble: BTDM memory released
I (28671) esp_rmaker_local: Event 6
I (28681) esp_rmaker_local: Starting ESP Local control with HTTP Transport and security version: 1
I (28701) esp_https_server: Starting server
I (28701) esp_https_server: Server listening on port 8080
I (28701) esp_rmaker_local: esp_local_ctrl service started with name : A0764E5A640C
W (28701) app_main: Unhandled RainMaker Event: 6
I (34571) wifi:bcn_timout,ap_probe_send_start
I (37071) wifi:ap_probe_send over, resett wifi status to disassoc
I (37071) wifi:state: run -> init (c800)
I (37071) wifi:pm stop, total sleep time: 1509242 us / 11011408 us

W (37071) wifi:<ba-del>idx
I (37081) wifi:new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1
I (37081) app_wifi: Disconnected. Connecting to the AP again...
E (37091) Dynamic Impl: mbedtls_ssl_fetch_input error=76
E (37091) esp-tls-mbedtls: mbedtls_ssl_handshake returned -0x004C
E (37101) esp-tls: Failed to open new connection
E (37111) TRANSPORT_BASE: Failed to open a new connection
E (37111) MQTT_CLIENT: Error transport connect
E (37121) esp_mqtt_glue: MQTT_EVENT_ERROR
W (37121) esp_mqtt_glue: MQTT Disconnected. Will try reconnecting in a while...
I (37131) app_main: MQTT Disconnected.
I (39141) app_wifi: Disconnected. Connecting to the AP again...
I (39141) wifi:new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1
I (39141) wifi:state: init -> auth (b0)
I (39151) wifi:state: auth -> assoc (0)
E (39151) wifi:Association refused temporarily, comeback time 1004 mSec
I (40161) wifi:state: assoc -> assoc (0)
E (40161) wifi:Association refused temporarily, comeback time 1004 mSec
I (41171) wifi:state: assoc -> assoc (0)
I (41171) wifi:state: assoc -> init (6c0)
I (41171) wifi:new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1
I (41171) app_wifi: Disconnected. Connecting to the AP again...
I (43231) app_wifi: Disconnected. Connecting to the AP again...
I (43231) wifi:new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1
I (43231) wifi:state: init -> auth (b0)
I (43921) wifi:state: auth -> assoc (0)
I (43931) wifi:state: assoc -> run (10)
I (43951) wifi:connected with Jacek, aid = 28, channel 11, BW20, bssid = e8:d2:ff:59:9c:a4
I (43951) wifi:security: WPA3-SAE, phy: bgn, rssi: -62
I (43951) wifi:pm start, type: 1

I (43951) wifi:set rx beacon pti, rx_bcn_pti: 14, bcn_timeout: 14, mt_pti: 25000, mt_time: 10000
W (44011) wifi:<ba-add>idx:0 (ifx:0, e8:d2:ff:59:9c:a4), tid:0, ssn:1, winSize:64
I (44031) wifi:BcnInt:102400, DTIM:3
I (45091) app_wifi: Connected with IP Address:192.168.1.63
I (45091) esp_netif_handlers: sta ip: 192.168.1.63, mask: 255.255.255.0, gw: 192.168.1.1
I (47681) esp-x509-crt-bundle: Certificate validated
I (49461) esp_mqtt_glue: MQTT Connected
I (49461) app_main: MQTT Connected.
I (49471) esp_rmaker_node_config: Reporting Node Configuration of length 1410 bytes.
I (49481) esp_rmaker_core: Waiting for User Node Association.
I (49481) esp_rmaker_ota_using_topics: Subscribing to: node/A0764E5A640C/otaurl
I (49491) esp_rmaker_ota_using_topics: Fetching OTA details, if any.
I (49501) esp_rmaker_user_mapping: MQTT Publish: {"node_id":"A0764E5A640C","user_id":"SignInWithApple_txxxxxxxxxxxxxxxxxxxx","secret_key":"xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx","reset":true}
I (50081) app_main: MQTT Published. Msg id: 35822.
I (50081) app_main: MQTT Published. Msg id: 36348.
I (50091) app_main: MQTT Published. Msg id: 23225.
I (50091) esp_rmaker_user_mapping: User Node association message published successfully.
W (50101) app_main: Unhandled RainMaker Event: 5
I (50101) esp_rmaker_param: Params MQTT Init done.
I (50111) esp_rmaker_param: Reporting params (init): {"Switch":{"Name":"Switch","Power":true},"Time":{"TZ":"","TZ-POSIX":""},"Schedule":{"Schedules":[]},"Scenes":{"Scenes":[]},"Local Control":{"POP":"a95d7f20","Type":1}}
I (50131) esp_rmaker_cmd_resp: Enabling Command-Response Module.
I (50691) app_main: MQTT Published. Msg id: 42936.
I (56831) esp_rmaker_param: Received params: {"Time":{"TZ":"Europe/Warsaw"}}
I (56841) esp_rmaker_time_service: Received value = Europe/Warsaw for Time - TZ
W (56841) app_main: Unhandled RainMaker Common Event: 6
I (56851) esp_rmaker_time: The current time is: Wed Jul 27 12:46:24 2022 +0200[CEST], DST: Yes.
W (56851) app_main: Unhandled RainMaker Common Event: 7
I (56861) esp_rmaker_param: Reporting params: {"Time":{"TZ-POSIX":"CET-1CEST,M3.5.0,M10.5.0/3"}}
I (56871) esp_rmaker_param: Reporting params: {"Time":{"TZ":"Europe/Warsaw"}}
I (57141) app_main: MQTT Published. Msg id: 1972.
I (57471) app_main: MQTT Published. Msg id: 16708.
I (68621) esp_rmaker_time: SNTP Synchronised.
I (68621) esp_rmaker_time: The current time is: Wed Jul 27 12:46:35 2022 +0200[CEST], DST: Yes.
jacek12345 commented 1 year ago

related with #147 . Resolved by updating ESP-IDF to release/v4.4 branch