Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

程序正常运行时出现mqtt和http无法连接，重连失败现象：esp-tls: Failed to open new connection；transport_base: Failed to open a new connection；HTTP_CLIENT: Connection failed, sock < 0 (IDFGH-13787) #14646

Open
3 tasks done
gl-LanYH opened this issue Sep 30, 2024 · 9 comments
Open
3 tasks done

程序正常运行时出现mqtt和http无法连接，重连失败现象：esp-tls: Failed to open new connection；transport_base: Failed to open a new connection；HTTP_CLIENT: Connection failed, sock < 0 (IDFGH-13787) #14646

gl-LanYH opened this issue Sep 30, 2024 · 9 comments
Assignees
@hansw123
Labels
Awaiting Response awaiting a response from the author Status: Reviewing Issue is being reviewed

Comments

@gl-LanYH
Copy link

Answers checklist.

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

General issue report

[19:41:28.492] D (206933) wifi_init_default: Got IP wifi default handler entered�[0m
[19:41:28.492] D (206933) esp_netif_handlers: esp_netif action got_ip with netif0x3fcba1dc from event_id=0�[0m
[19:41:28.492] �[0;32mI (206943) esp_netif_handlers: sta ip: 192.168.88.194, mask: 255.255.255.0, gw: 192.168.88.1�[0m
[19:41:28.492] D (206953) HTTP_CLIENT: Begin connect to: https://gslb.lafaer.cn:443�[0m
[19:41:28.492] D (206963) esp-tls: host:gslb.lafaer.cn: strlen 14�[0m
[19:41:28.492] D (206963) esp-tls: [sock=54] Resolved IPv4 address: 120.24.55.11�[0m
[19:41:28.492] D (206973) esp-tls: [sock=54] Connecting to server. HOST: gslb.lafaer.cn, Port: 443�[0m
[19:41:30.210] D (208723) esp-tls: handshake in progress...�[0m
[19:41:32.757] D (211233) mqtt_client: Reconnecting...�[0m
[19:41:32.762] D (211233) event: running post MQTT_EVENTS:7 with handler 0x420114a6 and context 0x3fca6f30 on loop 0x3fca7a48�[0m
[19:41:32.762] �[1;32m./main/src/gl_mqtt.c[191]: Other event id:7�[0m
[19:41:32.762] D (211233) esp-tls: host:120.24.55.11: strlen 12�[0m
[19:41:32.762] D (211243) esp-tls: [sock=55] Resolved IPv4 address: 120.24.55.11�[0m
[19:41:32.762] D (211243) esp-tls: [sock=55] Connecting to server. HOST: 120.24.55.11, Port: 8883�[0m
[19:41:35.137] D (213653) esp-tls: handshake in progress...�[0m
[19:41:37.113] �[0;33mW (215293) esp-tls: Failed to open new connection in specified timeout�[0m
[19:41:37.122] �[0;31mE (215293) transport_base: Failed to open a new connection�[0m
[19:41:37.122] �[0;31mE (215293) HTTP_CLIENT: Connection failed, sock < 0�[0m
[19:41:37.122] D (215293) HTTP_CLIENT: HTTP_EVENT_ERROR�[0m
[19:41:37.122] D (215303) event: no handlers have been registered for event ESP_HTTP_CLIENT_EVENT:0 posted to loop 0x3fca9fb8�[0m
[19:41:37.122] �[0;31mE (215313) HTTP_CLIENT: HTTP POST request failed: ESP_ERR_HTTP_CONNECT�[0m
[19:41:37.122] �[0;32mI (215313) HTTP_CLIENT: HTTP_EVENT_DISCONNECTED�[0m
[19:41:37.122] �[0;32mI (215323) HTTP_CLIENT: Last esp error code: 0x8006�[0m
[19:41:37.122] �[0;32mI (215333) HTTP_CLIENT: Last mbedtls failure: 0x0�[0m
[19:41:37.122] D (215333) event: no handlers have been registered for event ESP_HTTP_CLIENT_EVENT:6 posted to loop 0x3fca9fb8�[0m
[19:41:37.122] D (215343) event: running post BLE_NETWORK_EVENT:3 with handler 0x42014e30 and context 0x3fcba338 on loop 0x3fca9fb8�[0m
[19:41:37.122] �[1;32m./main/src/gl_network.c[329]: BLE_RPT_NETWORK_DISCONNECT�[0m
[19:41:37.122] �[1;32m./main/src/gl_network.c[345]: continue goto network�[0m
[19:41:37.122] D (215363) wifi:Start wifi disconnect
[19:41:37.122] I (215373) wifi:state: run -> init (0)
[19:41:37.122] D (215373) wifi:connect status 5 -> 6
[19:41:37.122] D (215383) wifi:stop beacon/connect timer, send diassoc(8)
[19:41:37.122] D (215383) wifi:sta leave
[19:41:37.122] I (215383) wifi:pm stop, total sleep time: 2665863 us / 10177093 us
[19:41:37.122]
[19:41:37.122] D (215393) wifi:stop CSA timer
[19:41:37.122] I (215393) wifi:idx:1, tid:0
[19:41:37.122] I (215393) wifi:idx:0, tid:7
[19:41:37.122] D (215403) wifi:remove 76:07:a6:f0:a8:4f from rc list
[19:41:37.122] I (215403) wifi:new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1
[19:41:37.122] D (215413) wifi:filter: set rx policy=8
[19:41:37.122] D (215413) wifi:Send disconnect event, reason=8, AP number=0
[19:41:37.122] D (215423) wifi:connect status 6 -> 0
[19:41:37.122] D (215423) wifi:filter: set rx policy=8
[19:41:37.122] D (215433) wifi:Start wifi connect
[19:41:37.122] D (215433) wifi:connect status 0 -> 0
[19:41:37.122] D (215433) wifi:connect chan=0
[19:41:37.122] D (215433) wifi:first chan=11
[19:41:37.122] D (215443) wifi:connect status 0 -> 1
[19:41:37.122] D (215443) wifi:filter: set rx policy=3
[19:41:37.122] D (215443) wifi:clear scan ap list
[19:41:37.122] D (215453) wifi:start scan: type=0x50f, priority=2, cb=0x420f36ce, arg=0x0, ss_state=0x1, time=215460798, index=0
[19:41:37.122] D (215463) wifi:perform scan: ss_state=0x9, chan<11,0>, dur<0,120>
[19:41:37.122] D (215463) event: running post WIFI_EVENT:5 with handler 0x42014e30 and context 0x3fcba2d4 on loop 0x3fca9fb8�[0m
[19:41:37.122] �[1;32m./main/src/gl_network.c[202]: Disconnect reason: 8�[0m
[19:41:37.122] �[1;32m./main/src/gl_network.c[232]: continue to connect wifi!�[0m
[19:41:37.122] D (215483) wifi:rsn valid: gcipher=3 ucipher=3 akm=5
[19:41:37.122]
[19:41:37.122] D (215493) wifi:profile match: ss_state=0x7
[19:41:37.122] D (215493) wifi:Start wifi connect
[19:41:37.122] E (215503) wifi:sta is connecting, return error
[19:41:37.122] D (215503) event: running post WIFI_EVENT:5 with handler 0x420a9238 and context 0x3fcbb768 on loop 0x3fca9fb8�[0m
[19:41:37.122] D (215513) esp_netif_handlers: esp_netif action disconnected with netif0x3fcba1dc from event_id=5�[0m
[19:41:37.122] D (215523) esp_netif_lwip: check: remote, if=0x3fcba1dc fn=0x420a6058
[19:41:37.122] �[0m
[19:41:37.122] D (215533) wifi:scan end: arg=0x0, status=0, ss_state=0x7
[19:41:37.122] D (215533) wifi:find first mathched ssid, scan done
[19:41:37.122] D (215543) wifi:filter: set rx policy=4
[19:41:37.122] D (215543) wifi:first chan=1
[19:41:37.122] D (215543) wifi:handoff_cb: status=0
[19:41:37.122] D (215553) wifi:ap found, mac=76:07:a6:f0:a8:4f
[19:41:37.122] D (215553) wifi:new_bss=0x3fc9f100, cur_bss=0x0, new_chan=<11,0>, cur_chan=11
[19:41:37.122] D (215563) wifi:filter: set rx policy=5
[19:41:37.122] I (215563) wifi:new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1
[19:41:37.122] D (215573) wifi:connect_op: status=0, auth=5, cipher=3
[19:41:37.122] D (215573) wifi:auth mode is not none
[19:41:37.122] D (215583) wifi:connect_bss: auth=1, reconnect=0
[19:41:37.122] I (215583) wifi:state: init -> auth (b0)
[19:41:37.122] D (215583) wifi:start 1s AUTH timer
[19:41:37.122] D (215593) wifi:clear scan ap list
[19:41:37.122] D (215593) esp_netif_lwip: esp_netif_down_api esp_netif:0x3fcba1dc�[0m
[19:41:37.122] D (215603) esp_netif_lwip: esp_netif_internal_dhcpc_cb lwip-netif:0x3fcbb52c�[0m
[19:41:37.122] D (215603) esp_netif_lwip: esp_netif_start_ip_lost_timer esp_netif:0x3fcba1dc�[0m
[19:41:37.122] D (215613) esp_netif_lwip: if0x3fcba1dc start ip lost tmr: already started�[0m
[19:41:37.122] D (215623) esp_netif_l
wip: esp_netif_start_ip_lost_timer esp_netif:0x3fcba1dc�[0m
[19:41:37.462] D (215623) esp_netif_lwip: if0x3fcba1dc start ip lost tmr: already started�[0m
[19:41:37.462] D (215633) esp_netif_lwip: check: local, if=0x3fcba1dc fn=0x420a682c
[19:41:37.462] �[0m
[19:41:37.462] D (215643) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3fcba1dc�[0m
[19:41:37.462] D (215643) esp_netif_lwip: call api in lwip: ret=0x0, give sem�[0m
[19:41:37.462] �[0;31mE (215653) esp-tls-mbedtls: mbedtls_ssl_handshake returned -0x004C�[0m
[19:41:37.462] �[0;32mI (215663) esp-tls-mbedtls: (FFFFFFB4): UNKNOWN ERROR CODE (004C)�[0m
[19:41:37.462] �[0;32mI (215663) esp-tls-mbedtls: Certificate verified.�[0m
[19:41:37.462] �[0;31mE (215673) esp-tls: Failed to open new connection�[0m
[19:41:37.462] �[0;31mE (215673) transport_base: Failed to open a new connection�[0m
[19:41:37.462] D (215663) wifi:recv auth: seq=2, status=0
[19:41:37.462] I (215683) wifi:state: auth -> assoc (0)
[19:41:37.462] D (215693) wifi:restart connect 1s timer for assoc
[19:41:37.462] �[0;31mE (215693) mqtt_client: Error transport connect�[0m
[19:41:37.462] D (215703) event: running post MQTT_EVENTS:0 with handler 0x420114a6 and context 0x3fca6f30 on loop 0x3fca7a48�[0m
[19:41:37.462] �[1;31m./main/src/gl_mqtt.c[181]: MQTT_EVENT_ERROR�[0m
[19:41:37.462] �[0;32mI (215713) mqtt_client: Client asked to disconnect�[0m
[19:41:37.462] D (215723) wifi:Start wifi disconnect
[19:41:37.462] I (215723) wifi:state: assoc -> init (0)
[19:41:37.462] D (215733) wifi:connect status 1 -> 4
[19:41:37.462] D (215733) wifi:stop beacon/connect timer
[19:41:37.462] D (215733) wifi:add bssid 76:07:a6:f0:a8:4f to blacklist, cnt=0
[19:41:37.462] D (215743) wifi:stop CSA timer
[19:41:37.462] D (215743) wifi:remove 76:07:a6:f0:a8:4f from rc list
[19:41:37.462] I (215753) wifi:new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1
[19:41:37.462] D (215753) wifi:filter: set rx policy=8
[19:41:37.462] D (215763) wifi:reason: assoc fail(rc - 0)
[19:41:37.462] D (215763) wifi:Send disconnect event, reason=203, AP number=0
[19:41:37.462] D (215773) wifi:connect status 4 -> 0
[19:41:37.462] D (215773) wifi:filter: set rx policy=8
[19:41:37.462] D (215773) event: running post WIFI_EVENT:5 with handler 0x42014e30 and context 0x3fcba2d4 on loop 0x3fca9fb8�[0m
[19:41:37.462] �[1;32m./main/src/gl_network.c[202]: Disconnect reason: 203�[0m
[19:41:37.462] �[1;32m./main/src/gl_network.c[232]: continue to connect wifi!�[0m
[19:41:37.462] D (215793) wifi:Start wifi connect
[19:41:37.462] D (215803) wifi:connect status 0 -> 0
[19:41:37.462] D (215803) wifi:connect chan=0
[19:41:37.462] D (215803) wifi:first chan=11
[19:41:37.462] D (215813) wifi:connect status 0 -> 1
[19:41:37.462] D (215813) wifi:filter: set rx policy=3
[19:41:37.462] D (215813) wifi:clear scan ap list
[19:41:37.462] D (215823) wifi:start scan: type=0x50f, priority=2, cb=0x420f36ce, arg=0x0, ss_state=0x1, time=215829514, index=0
[19:41:37.462] D (215833) wifi:perform scan: ss_state=0x9, chan<11,0>, dur<0,120>
[19:41:37.462] D (215833) event: running post WIFI_EVENT:5 with handler 0x420a9238 and context 0x3fcbb768 on loop 0x3fca9fb8�[0m
[19:41:37.462] D (215843) esp_netif_handlers: esp_netif action disconnected with netif0x3fcba1dc from event_id=5�[0m
[19:41:37.462] D (215853) esp_netif_lwip: check: remote, if=0x3fcba1dc fn=0x420a6058
[19:41:37.462] �[0m
[19:41:37.462] D (215863) esp_netif_lwip: esp_netif_down_api esp_netif:0x3fcba1dc�[0m
[19:41:37.462] D (215863) esp_netif_lwip: esp_netif_start_ip_lost_timer esp_netif:0x3fcba1dc�[0m
[19:41:37.462] D (215873) wifi:Start wifi connect
[19:41:37.462] E (215873) wifi:sta is connecting, return error
[19:41:37.462] D (215883) mqtt_client: Reconnect after 10000 ms�[0m
[19:41:37.462] D (215883) event: running post MQTT_EVENTS:2 with handler 0x420114a6 and context 0x3fca6f30 on loop 0x3fca7a48�[0m
[19:41:37.462] �[1;32m./main/src/gl_mqtt.c[140]: MQTT_EVENT_DISCONNECTED�[0m
[19:41:37.462] �[1;32m./components/gl_common/src/gl_common.c[405]: *************************************************************�[0m
[19:41:37.462] �[1;32m./components/gl_common/src/gl_common.c[406]: esp_get_free_heap_size : 84392 bytes�[0m
[19:41:37.462] �[1;32m./components/gl_common/src/gl_common.c[407]: esp_get_free_internal_heap_size : 76620 bytes�[0m
[19:41:37.462] �[1;32m./components/gl_common/src/gl_common.c[408]: esp_get_minimum_free_heap_size : 1292 bytes�[0m
[19:41:37.462] �[1;32m./components/gl_common/src/gl_common.c[409]: heap_caps_get_largest_free_block : 34816 bytes�[0m
[19:41:37.462] �[1;32m./components/gl_common/src/gl_common.c[410]: *************************************************************�[0m
[19:41:37.462] D (215963) esp_netif_lwip: if0x3fcba1dc start ip lost tmr: already started�[0m
[19:41:37.462] D (215963) esp_netif_lwip: check: local, if=0x3fcba1dc fn=0x420a682c
[19:41:37.491] �[0m
[19:41:37.491] D (215973) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3fcba1dc�[0m
[19:41:37.491] D (215983) esp_netif_lwip: call api in lwip: ret=0x0, give sem�[0m
[19:41:37.582] D (216073) wifi:scan end: arg=0x0, status=0, ss_state=0x3
[19:41:37.592] D (216073) wifi:perform scan: ss_state=0x9, chan<1,0>, dur<0,120>
[19:41:37.825] D (216313) wifi:scan end: arg=0x0, status=0, ss_state=0x3
[19:41:37.832] D (216323) wifi:perform scan: ss_state=0x9, chan<2,0>, dur<0,120>
[19:41:38.066] D (216563) wifi:scan end: arg=0x0, status=0, ss_state=0x3
[19:41:38.071] D (216563) wifi:perform scan: ss_state=0x9, chan<3,0>, dur<0,120>
[19:41:38.309] D (216803) wifi:scan end: arg=0x0, status=0, ss_state=0x3
[19:41:38.312] D (216803) wifi:perform scan: ss_state=0x9, chan<4,0>, dur<0,120>
[19:41:38.551] D (217043) wifi:scan end: arg=0x0, status=0, ss_state=0x3
[19:41:38.553] D (217043) wifi:perform scan: ss_state=0x9, chan<5,0>, dur<0,120>
[19:41:38.792] D (217283) wifi:scan end: arg=0x0, status=0, ss_state=0x3
[19:41:38.801] D (217283) wifi:perform scan: ss_state=0x9, chan<6,0>, dur<0,120>
[19:41:39.034] D (217523) wifi:scan end: arg=0x0, status=0, ss_state=0x3
[19:41:39.042] D (217523) wifi:perform scan: ss_state=0x9, chan<7,0>, dur<0,120>
[19:41:39.276] D (217773) wifi:scan end: arg=0x0, status=0, ss_state=0x3
[19:41:39.282] D (217773) wifi:perform scan: ss_state=0x9, chan<8,0>, dur<0,120>
[19:41:39.518] D (218013) wifi:scan end: arg=0x0, status=0, ss_state=0x3
[19:41:39.523] D (218013) wifi:perform scan: ss_state=0x9, chan<9,0>, dur<0,120>
[19:41:39.760] D (218253) wifi:scan end: arg=0x0, status=0, ss_state=0x3
[19:41:39.762] D (218253) wifi:perform scan: ss_state=0x9, chan<10,0>, dur<0,120>
[19:41:40.002] D (218493) wifi:scan end: arg=0x0, status=0, ss_state=0x3
[19:41:40.012] D (218493) wifi:perform scan: ss_state=0x9, chan<12,0>, dur<360,360>
[19:41:40.244] D (218733) wifi:scan end: arg=0x0, status=0, ss_state=0x3
[19:41:40.252] D (218733) wifi:perform scan: ss_state=0x9, chan<13,0>, dur<360,360>
[19:41:40.486] D (218973) wifi:scan end: arg=0x0, status=0, ss_state=0x3
[19:41:40.492] D (218983) wifi:perform scan: ss_state=0x9, chan<14,0>, dur<360,360>
[19:41:40.958] D (219223) wifi:scan end: arg=0x0, status=0, ss_state=0x3
[19:41:40.962] D (219223) wifi:filter: set rx policy=4
[19:41:40.962] D (219223) wifi:first chan=1
[19:41:40.962] D (219223) wifi:handoff_cb: status=0
[19:41:40.962] D (219223) wifi:clear blacklist
[19:41:40.962] D (219223) wifi:clear rc list
[19:41:40.962] D (219233) wifi:clear blacklist
[19:41:40.962] D (219233) wifi:Send disconnect event, reason=201
[19:41:40.962] D (219233) wifi:connect status 1 -> 3
[19:41:40.962] D (219243) wifi:disable connect timer
[19:41:40.962] D (219243) wifi:clear scan ap list
[19:41:40.962] D (219243) event: running post WIFI_EVENT:5 with handler 0x42014e30 and context 0x3fcba2d4 on loop 0x3fca9fb8�[0m
[19:41:40.962] �[1;32m./main/src/gl_network.c[202]: Disconnect reason: 201�[0m
[19:41:40.962] �[1;32m./main/src/gl_network.c[232]: continue to connect wifi!�[0m
[19:41:40.962] D (219263) wifi:Start wifi connect
[19:41:40.962] D (219273) wifi:connect status 3 -> 0
[19:41:40.962] D (219273) wifi:connect chan=0
[19:41:40.962] D (219273) wifi:first chan=11
[19:41:40.962] D (219283) wifi:connect status 0 -> 1
[19:41:40.962] D (219283) wifi:filter: set rx policy=3
[19:41:40.962] D (219283) wifi:clear scan ap list
[19:41:40.962] D (219293) wifi:start scan: type=0x50f, priority=2, cb=0x420f36ce, arg=0x0, ss_state=0x1, time=219300336, index=0
[19:41:40.962] D (219303) wifi:perform scan: ss_state=0x9, chan<11,0>, dur<0,120>
[19:41:40.962] D (219303) event: running post WIFI_EVENT:5 with handler 0x420a9238 and context 0x3fcbb768 on loop 0x3fca9fb8�[0m
[19:41:40.962] D (219313) esp_netif_handlers: esp_netif action disconnected with netif0x3fcba1dc from event_id=5�[0m
[19:41:40.962] D (219323) esp_netif_lwip: check: remote, if=0x3fcba1dc fn=0x420a6058
[19:41:40.962] �[0m
[19:41:40.962] D (219333) wifi:rsn valid: gcipher=3 ucipher=3 akm=5
[19:41:40.962]
[19:41:40.962] D (219333) wifi:profile match: ss_state=0x7
[19:41:40.962] D (219343) wifi:scan end: arg=0x0, status=0, ss_state=0x7
[19:41:40.962] D (219343) wifi:find first mathched ssid, scan done
[19:41:40.962] D (219353) wifi:filter: set rx policy=4
[19:41:40.962] D (219353) wifi:first chan=1
[19:41:40.962] D (219353) wifi:handoff_cb: status=0
[19:41:40.962] D (219363) wifi:ap found, mac=76:07:a6:f0:a8:4f
[19:41:40.962] D (219363) wifi:new_bss=0x3fc9f100, cur_bss=0x0, new_chan=<11,0>, cur_chan=11
[19:41:40.962] D (219373) wifi:filter: set rx policy=5
[19:41:40.962] I (219373) wifi:new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1
[19:41:40.962] D (219383) wifi:connect_op: status=0, auth=5, cipher=3
[19:41:40.962] D (219383) wifi:auth mode is not none
[19:41:40.962] D (219393) wifi:connect_bss: auth=1, reconnect=0
[19:41:40.962] I (219393) wifi:state: init -> auth (b0)
[19:41:40.962] D (219393) wifi:start 1s AUTH timer
[19:41:40.962] D (219403) wifi:clear scan ap list
[19:41:40.962] D (219403) esp_netif_lwip: esp_netif_down_api esp_netif:0x3fcba1dc�[0m
[19:41:40.962] D (219413) esp_netif_lwip: esp_netif_start_ip_lost_timer esp_netif:0x3fcba1dc�[0m
[19:41:40.962] D (219413) esp_netif_lwip: if0x3fcba1dc start ip lost tmr: already started�[0m
[19:41:40.962] D (219423) wifi:recv auth: seq=2, status=0
[19:41:40.962] I (219423) wifi:state: auth -> assoc (0)
[19:41:40.962] D (219433) wifi:restart connect 1s timer for assoc
[19:41:40.962] D (219433) esp_netif_lwip: check: local, if=0x3fcba1dc fn=0x420a682c
[19:41:40.962] �[0m
[19:41:40.962] D (219443) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3fcba1dc�[0m
[19:41:40.962] D (219453) esp_netif_lwip: call api in lwip: ret=0x0, give sem�[0m
[19:41:41.008] D (219503) wifi:recv assoc: type=0x10
[19:41:41.012] D (219503) wifi:filter: set rx policy=6
[19:41:41.012] I (219503) wifi:state: assoc -> run (10)
[19:41:41.012] D (219503) wifi:start 10s connect timer for 4 way handshake
[19:41:41.473] I (219793) wifi:connected with GL-MT6000-af7, aid = 6, channel 11, BW20, bssid = 76:07:a6:f0:a8:4f
[19:41:41.482] I (219793) wifi:security: WPA2-PSK, phy: bgn, rssi: -30
[19:41:41.482] D (219793) wifi:remove all except 76:07:a6:f0:a8:4f from rc list
[19:41:41.482] D (219803) wifi:clear blacklist
[19:41:41.482] D (219803) nvs: nvs_set sta.chan 1 11�[0m
[19:41:41.482] D (219803) nvs: nvs_set_blob sta.apinfo 700�[0m
[19:41:41.482] D (219813) wifi:filter: set rx policy=7
[19:41:41.482] I (219813) wifi:pm start, type: 1
[19:41:41.482]
[19:41:41.482] I (219823) wifi:set rx beacon pti, rx_bcn_pti: 14, bcn_timeout: 25000, mt_pti: 14, mt_time: 10000
[19:41:41.482] D (219823) wifi:Send sta connected event
[19:41:41.482] D (219833) wifi:connect status 1 -> 5
[19:41:41.482] D (219833) wifi:obss scan is disabled
[19:41:41.482] D (219833) wifi:start obss scan: obss scan is stopped
[19:41:41.482] I (219843) wifi:AP's beacon interval = 102400 us, DTIM period = 1
[19:41:41.482] D (219853) wifi:set max rate: from <rate=130, phy=3, sig=0> to <rate=144, phy=3 sig=0>
[19:41:41.482] D (219853) wifi:sig_b=0, sig_g=0, sig_n=0, max_b=22, max_g=108, max_n=144
[19:41:41.482] D (219863) wifi:update trc
[19:41:41.482] D (219863) event: running post WIFI_EVENT:4 with handler 0x42014e30 and context 0x3fcba2d4 on loop 0x3fca9fb8�[0m
[19:41:41.482] �[1;32m./main/src/gl_network.c[196]: WIFI_EVENT_STA_CONNECTED�[0m
[19:41:41.482] D (219883) event: running post WIFI_EVENT:4 with handler 0x420a9252 and context 0x3fcbb738 on loop 0x3fca9fb8�[0m
[19:41:41.482] D (219893) esp_netif_handlers: esp_netif action connected with netif0x3fcba1dc from event_id=4�[0m
[19:41:41.482] D (219903) esp_netif_lwip: check: remote, if=0x3fcba1dc fn=0x420a5fe2
[19:41:41.482] �[0m
[19:41:41.482] D (219903) esp_netif_lwip: esp_netif_up_api esp_netif:0x3fcba1dc�[0m
[19:41:41.482] D (219913) esp_netif_lwip: check: local, if=0x3fcba1dc fn=0x420a682c
[19:41:41.482] �[0m
[19:41:41.482] D (219923) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3fcba1dc�[0m
[19:41:41.482] D (219923) esp_netif_lwip: call api in lwip: ret=0x0, give sem�[0m
[19:41:41.482] D (219933) esp_netif_lwip: check: remote, if=0x3fcba1dc fn=0x420a5e1e
[19:41:41.482] �[0m
[19:41:41.482] D (219933) esp_netif_lwip: esp_netif_dhcpc_start_api esp_netif:0x3fcba1dc�[0m
[19:41:41.482] D (219943) esp_netif_lwip: esp_netif_start_ip_lost_timer esp_netif:0x3fcba1dc�[0m
[19:41:41.482] D (219953) esp_netif_lwip: if0x3fcba1dc start ip lost tmr: already started�[0m
[19:41:41.482] D (219963) esp_netif_lwip: starting dhcp client�[0m
[19:41:41.482] D (219963) esp_netif_lwip: call api in lwip: ret=0x0, give sem�[0m
[19:41:41.950] I (220473) wifi:idx:0 (ifx:0, 76:07:a6:f0:a8:4f), tid:7, ssn:1, winSize:64
[19:41:42.041] I (220543) wifi:idx:1 (ifx:0, 76:07:a6:f0:a8:4f), tid:0, ssn:2, winSize:64
[19:41:43.095] D (221463) esp_netif_lwip: esp_netif_internal_dhcpc_cb lwip-netif:0x3fcbb52c�[0m
[19:41:43.102] D (221463) esp_netif_lwip: if0x3fcba1dc ip changed=0�[0m
[19:41:43.102] D (221463) event: running post IP_EVENT:0 with handler 0x42014e30 and context 0x3fcba280 on loop 0x3fca9fb8�[0m
[19:41:43.102] �[1;32m./main/src/gl_network.c[139]: IP_EVENT_STA_GOT_IP�[0m
[19:41:43.102] �[1;32m./components/gl_common/src/gl_common.c[405]: *************************************************************�[0m
[19:41:43.102] �[1;32m./components/gl_common/src/gl_common.c[406]: esp_get_free_heap_size : 89124 bytes�[0m
[19:41:43.102] �[1;32m./components/gl_common/src/gl_common.c[407]: esp_get_free_internal_heap_size : 81480 bytes�[0m
[19:41:43.102] �[1;32m./components/gl_common/src/gl_common.c[408]: esp_get_minimum_free_heap_size : 1292 bytes�[0m
[19:41:43.102] �[1;32m./components/gl_common/src/gl_common.c[409]: heap_caps_get_largest_free_block : 34816 bytes�[0m
[19:41:43.102] �[1;32m./components/gl_common/src/gl_common.c[410]: *************************************************************�[0m
[19:41:43.102] D (221533) event: running post IP_EVENT:0 with handler 0x420a8fae and context 0x3fcbb7f8 on loop 0x3fca9fb8�[0m
[19:41:43.102] D (221543) wifi_init_default: Got IP wifi default handler entered�[0m
[19:41:43.102] D (221543) esp_netif_handlers: esp_netif action got_ip with netif0x3fcba1dc from event_id=0�[0m
[19:41:43.102] �[0;32mI (221553) esp_netif_handlers: sta ip: 192.168.88.194, mask: 255.255.255.0, gw: 192.168.88.1�[0m
[19:41:43.102] D (221563) HTTP_CLIENT: Begin connect to: https://gslb.lafaer.cn:443�[0m
[19:41:43.102] D (221573) esp-tls: host:gslb.lafaer.cn: strlen 14�[0m
[19:41:43.102] D (221573) esp-tls: [sock=54] Resolved IPv4 address: 120.24.55.11�[0m
[19:41:43.102] D (221583) esp-tls: [sock=54] Connecting to server. HOST: gslb.lafaer.cn, Port: 443�[0m
[19:41:47.506] D (225983) mqtt_client: Reconnecting...�[0m
[19:41:47.512] D (225983) event: running post MQTT_EVENTS:7 with handler 0x420114a6 and context 0x3fca6f30 on loop 0x3fca7a48�[0m
[19:41:47.512] �[1;32m./main/src/gl_mqtt.c[191]: Other event id:7�[0m
[19:41:47.512] D (225983) esp-tls: host:120.24.55.11: strlen 12�[0m
[19:41:47.512] D (225993) esp-tls: [sock=55] Resolved IPv4 address: 120.24.55.11�[0m
[19:41:47.512] D (225993) esp-tls: [sock=55] Connecting to server. HOST: 120.24.55.11, Port: 8883�[0m
[19:41:48.081] �[0;31mE (226603) esp-tls: [s
ock=54] select() timeout�[0m
[19:41:48.432] �[0;31mE (226603) esp-tls: Failed to open new connection�[0m
[19:41:48.432] �[0;31mE (226603) transport_base: Failed to open a new connection�[0m
[19:41:48.432] �[0;31mE (226603) HTTP_CLIENT: Connection failed, sock < 0�[0m
[19:41:48.432] D (226613) HTTP_CLIENT: HTTP_EVENT_ERROR�[0m
[19:41:48.432] D (226613) event: no handlers have been registered for event ESP_HTTP_CLIENT_EVENT:0 posted to loop 0x3fca9fb8�[0m
[19:41:48.432] �[0;31mE (226623) HTTP_CLIENT: HTTP POST request failed: ESP_ERR_HTTP_CONNECT�[0m
[19:41:48.432] �[0;32mI (226633) HTTP_CLIENT: HTTP_EVENT_DISCONNECTED�[0m
[19:41:48.432] �[0;32mI (226633) HTTP_CLIENT: Last esp error code: 0x8006�[0m
[19:41:48.432] �[0;32mI (226643) HTTP_CLIENT: Last mbedtls failure: 0x0�[0m
[19:41:48.432] D (226643) event: no handlers have been registered for event ESP_HTTP_CLIENT_EVENT:6 posted to loop 0x3fca9fb8�[0m
[19:41:48.432] D (226653) event: running post BLE_NETWORK_EVENT:3 with handler 0x42014e30 and context 0x3fcba338 on loop 0x3fca9fb8�[0m
@espressif-bot espressif-bot added the Status: Opened Issue is new label Sep 30, 2024
@github-actions github-actions bot changed the title 程序正常运行时出现mqtt和http无法连接，重连失败现象：esp-tls: Failed to open new connection；transport_base: Failed to open a new connection；HTTP_CLIENT: Connection failed, sock < 0 程序正常运行时出现mqtt和http无法连接，重连失败现象：esp-tls: Failed to open new connection；transport_base: Failed to open a new connection；HTTP_CLIENT: Connection failed, sock < 0 (IDFGH-13787) Sep 30, 2024
@hansw123
Copy link
Collaborator

hansw123 commented Oct 9, 2024

@gl-LanYH
从log 看，在发生断开连接时，wifi事件的处理是重新连接，mqtt 在此期间好像还会通信，然后通信失败的事件处理是断开连接重新连接，这就打断了wifi的重新连接。
麻烦确认相应的事件处理函数，和上层协议通信的逻辑有没有判断wifi连接的状态。如果能提供更多的信息就更好定位问题，谢谢！

@espressif-bot espressif-bot added Status: In Progress Work is in progress and removed Status: Opened Issue is new labels Oct 10, 2024
@espressif-bot espressif-bot assigned hansw123 and unassigned hansw123 Oct 10, 2024
@espressif-bot espressif-bot added Status: Reviewing Issue is being reviewed and removed Status: In Progress Work is in progress labels Oct 12, 2024
@gl-LanYH
Copy link
Author

@gl-LanYH 从log 看，在发生断开连接时，wifi事件的处理是重新连接，mqtt 在此期间好像还会通信，然后通信失败的事件处理是断开连接重新连接，这就打断了wifi的重新连接。 麻烦确认相应的事件处理函数，和上层协议通信的逻辑有没有判断wifi连接的状态。如果能提供更多的信息就更好定位问题，谢谢！

@hansw123 感谢您的回复，我所使用的设备型号是esp32c3，idf版本为5.1.2；我说下我这边的大概逻辑：mqtt的登录信息是通过访问http服务获取的，且获取mqtt的登录信息存在有限的周期，在这期限内只要不使用就会失效，失效后要重新获取；所以当遇到mqtt连接失败或者错误后我会暂停mqtt的继续重连，并重启wifi能正确获取到IP（确保网络可用）后再去重新访问http服务器获取mqtt登录信息重新登录，这期间会将旧的mqtt_client destroy并初始化新的mqtt_client ，以及调用esp_http_client_cleanup将http释放

@hansw123
Copy link
Collaborator

@gl-LanYH
从您的描述来看，应该是当wifi disconnect 事件发生时，会进行wifi重新连接。然后这时mqtt 重启wifi导致正在连接的wifi 被打断，再然后有点陷入循环的意思，建议mqtt 这里就不要wifi重启了，因为已经有相应的事件处理进行重新连接了，只需要等待got ip事件再操作。或者重新连接的事件处理函数就删除，只在mqtt 这边处理。

@hansw123
Copy link
Collaborator

@gl-LanYH
同时可以使用api esp_wifi_sta_get_ap_info() 查询wifi 连接状态，重新调整应用逻辑，最好确保mqtt 操作前可以确定wifi的连接状态。

@gl-LanYH
Copy link
Author

@gl-LanYH 同时可以使用api esp_wifi_sta_get_ap_info() 查询wifi 连接状态，重新调整应用逻辑，最好确保mqtt 操作前可以确定wifi的连接状态。

感谢您提供的帮助！我在更换了另一个网络环境后暂未发现无法重连的现象。不过我这还遇到一种现象就是我在模拟弱网的环境下，重复上述逻辑中的重连wifi，http，mqtt的动作中发现 esp_get_minimum_free_heap_size 在不断缩小，挂载两天后由esp_get_minimum_free_heap_size : 39328 bytes 缩小到后来的 esp_get_minimum_free_heap_size : 200 bytes，虽然在网络良好的情况下能够重连上，但重连的时间也会时长时短，所以不确定esp_get_minimum_free_heap_size 的不断缩小是否会带来其他风险，我将继续挂载设备，下面附上一段日志：
�[1;32m./main/src/gl_network.c[202]: Disconnect reason: 201�[0m
�[1;32m./main/src/gl_network.c[232]: continue to connect wifi!�[0m
I (98287029) wifi:new:<3,1>, old:<3,0>, ap:<255,255>, sta:<3,1>, prof:1
I (98287029) wifi:state: init -> auth (b0)
I (98288029) wifi:state: auth -> init (200)
I (98288029) wifi:new:<3,0>, old:<3,1>, ap:<255,255>, sta:<3,1>, prof:1
�[1;32m./main/src/gl_network.c[202]: Disconnect reason: 2�[0m
�[1;32m./main/src/gl_network.c[232]: continue to connect wifi!�[0m
�[1;32m./main/src/gl_network.c[202]: Disconnect reason: 205�[0m
�[1;32m./main/src/gl_network.c[232]: continue to connect wifi!�[0m
I (98291429) wifi:new:<3,1>, old:<3,0>, ap:<255,255>, sta:<3,1>, prof:1
I (98291429) wifi:state: init -> auth (b0)
I (98291459) wifi:state: auth -> assoc (0)
I (98291469) wifi:state: assoc -> run (10)
I (98291549) wifi:connected with TEST-LYH-S1300-2.4G, aid = 2, channel 3, 40U, bssid = 94:83:c4:06:53:1b
I (98291549) wifi:security: WPA2-PSK, phy: bgn, rssi: -21
I (98291549) wifi:pm start, type: 1
I (98291559) wifi:set rx beacon pti, rx_bcn_pti: 14, bcn_timeout: 25000, mt_pti: 14, mt_time: 10000
�[1;32m./main/src/gl_network.c[196]: WIFI_EVENT_STA_CONNECTED�[0m
I (98291579) wifi:AP's beacon interval = 102400 us, DTIM period = 1
I (98291589) wifi:idx:0 (ifx:0, 94:83:c4:06:53:1b), tid:6, ssn:2, winSize:64
�[1;32m./main/src/gl_network.c[139]: IP_EVENT_STA_GOT_IP�[0m
�[1;32m./components/gl_common/src/gl_common.c[405]: *************************************************************�[0m
�[1;32m./components/gl_common/src/gl_common.c[406]: esp_get_free_heap_size : 89704 bytes�[0m
�[1;32m./components/gl_common/src/gl_common.c[407]: esp_get_free_internal_heap_size : 81932 bytes�[0m
�[1;32m./components/gl_common/src/gl_common.c[408]: esp_get_minimum_free_heap_size : 39328 bytes�[0m
�[1;32m./components/gl_common/src/gl_common.c[409]: heap_caps_get_largest_free_block : 34816 bytes�[0m
�[1;32m./components/gl_common/src/gl_common.c[410]: *************************************************************�[0m
�[0;32mI (98292619) esp_netif_handlers: sta ip: 192.168.7.194, mask: 255.255.255.0, gw: 192.168.7.1�[0m
I (98292739) wifi:idx:1 (ifx:0, 94:83:c4:06:53:1b), tid:0, ssn:0, winSize:64
�[1;32m./main/src/gl_mqtt.c[191]: Other event id:7�[0m
�[0;33mW (98294389) mqtt_client: Connection refused, bad username or password�[0m
�[1;31m./main/src/gl_mqtt.c[181]: MQTT_EVENT_ERROR�[0m
�[0;32mI (98294389) mqtt_client: Client asked to disconnect�[0m
I (98294399) wifi:state: run -> init (0)
I (98294399) wifi:pm stop, total sleep time: 1484887 us / 2843325 us
I (98294409) wifi:idx:1, tid:0
I (98294409) wifi:idx:0, tid:6
I (98294409) wifi:new:<3,0>, old:<3,1>, ap:<255,255>, sta:<3,1>, prof:1
�[1;32m./main/src/gl_network.c[202]: Disconnect reason: 8�[0m
�[1;32m./main/src/gl_network.c[232]: continue to connect wifi!�[0m
�[0;31mE (98294429) transport_base: poll_read select error 113, errno = Software caused connection abort, fd = 54�[0m
�[0;31mE (98294439) HTTP_CLIENT: HTTP POST request failed: ESP_ERR_HTTP_FETCH_HEADER�[0m
�[0;32mI (98294449) HTTP_CLIENT: HTTP_EVENT_DISCONNECTED�[0m
I (98294449) wifi:new:<3,1>, old:<3,0>, ap:<255,255>, sta:<3,1>, prof:1
I (98294459) wifi:state: init -> auth (b0)
�[1;32m./main/src/gl_network.c[345]: continue goto network�[0m
I (98294479) wifi:state: auth -> init (8a0)
I (98294479) wifi:new:<3,0>, old:<3,1>, ap:<255,255>, sta:<3,1>, prof:1
�[1;32m./main/src/gl_network.c[202]: Disconnect reason: 202�[0m
�[1;32m./main/src/gl_network.c[232]: continue to connect wifi!�[0m
E (98294499) wifi:sta is connecting, return error
E (98294529) wifi:sta is connecting, return error
�[0;31mE (98294529) mqtt_client: MQTT connect failed�[0m
�[1;32m./main/src/gl_mqtt.c[140]: MQTT_EVENT_DISCONNECTED�[0m
�[1;32m./components/gl_common/src/gl_common.c[405]: *************************************************************�[0m
�[1;32m./components/gl_common/src/gl_common.c[406]: esp_get_free_heap_size : 89972 bytes�[0m
�[1;32m./components/gl_common/src/gl_common.c[407]: esp_get_free_internal_heap_size : 82200 bytes�[0m
�[1;32m./components/gl_common/src/gl_common.c[408]: esp_get_minimum_free_heap_size : 2524 bytes�[0m
�[1;32m./components/gl_common/src/gl_common.c[409]: heap_caps_get_largest_free_block : 34816 bytes�[0m
�[1;32m./components/gl_common/src/gl_common.c[410]: *************************************************************�[0m
�[1;32m./main/src/gl_network.c[202]: Disconnect reason: 205�[0m
�[1;32m./main/src/gl_network.c[232]: continue to connect wifi!�[0m
I (98297899) wifi:new:<3,1>, old:<3,0>, ap:<255,255>, sta:<3,1>, prof:1
I (98297899) wifi:state: init -> auth (b0)
I (98297909) wifi:state: auth -> assoc (0)
I (98297929) wifi:state: assoc -> run (10)
I (98297969) wifi:connected with TEST-LYH-S1300-2.4G, aid = 2, channel 3, 40U, bssid = 94:83:c4:06:53:1b
I (98297979) wifi:security: WPA2-PSK, phy: bgn, rssi: -22
I (98297979) wifi:pm start, type: 1
I (98297979) wifi:set rx beacon pti, rx_bcn_pti: 14, bcn_timeout: 25000, mt_pti: 14, mt_time: 10000
�[1;32m./main/src/gl_network.c[196]: WIFI_EVENT_STA_CONNECTED�[0m
I (98298029) wifi:AP's beacon interval = 102400 us, DTIM period = 1
I (98298049) wifi:idx:0 (ifx:0, 94:83:c4:06:53:1b), tid:6, ssn:2, winSize:64
I (98298069) wifi:idx:1 (ifx:0, 94:83:c4:06:53:1b), tid:0, ssn:1, winSize:64

@hansw123
Copy link
Collaborator

@gl-LanYH
minimum_free_heap_size 是最值，只记录运行过程中的最小情况，
要关心内存变化，最好是定期打印free_heap_size，这个是反映 current free heap size

@REEASD
Copy link

REEASD commented Nov 12, 2024

我也有这个问题，设备在运行大概2条后就容易出现[20:01:23.451]收←◆�[0;33mW (107933554) esp-tls: Failed to open new connection in specified timeout�[0m
�[0;31mE (107933554) transport_base: Failed to open a new connection�[0m
�[0;31mE (107933559) HTTP_CLIENT: Connection failed, sock < 0�[0m的问题

@REEASD
Copy link

REEASD commented Nov 12, 2024

当出现该情况后，通过esp_get_free_heap_size 获取的大小是一直在变小的。此后每次出现esp-tls: Failed to open new connection in specified timeout，该内存就减小一点。具体变小的来源是psarm,我有设置SPIRAM_TRY_ALLOCATE_WIFI_LWIP等选项。期间我确认的事项是期间htttpss上报的服务器有重新部署。从现象看，似乎是当出现服务器异常导致的http 超时，但是似乎有资源在该状态下未被释放

@hansw123
Copy link
Collaborator

@REEASD
如果是server 出现问题导致tcp 的连接出现问题，根据协议是有固定的一些操作以及等待时间的，只有这些超时达成，才会回收连接的资源。具体的比如说tcp 四次挥手中的TIME_WAIT 阶段的时间

@Alvin1Zhang Alvin1Zhang added the Awaiting Response awaiting a response from the author label Dec 25, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@hansw123 hansw123

Labels
Awaiting Response awaiting a response from the author Status: Reviewing Issue is being reviewed
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
6 participants
@Alvin1Zhang @REEASD @espressif-bot @hansw123 @nileshkale123 @gl-LanYH