Page 1 of 1

esp_http_client post failing to timeout in bad Wi-Fi

Posted: Mon Jan 27, 2020 4:52 pm
by BrettG
I am running into issues sending a post over a bad wireless network (network simply too far away for reliable transmission) where it sometimes gets stuck sending data to the server and does not timeout after 5 seconds as it has been setup in esp_http_client_init.

This test is currently running on esp-idf 3.3.1 but have had similar failures on 3.2.X. I have found that the larger the file being sent the more likely it is to get stuck. And when the transmission does get stuck it also does not trigger the watchdog as it is supposed to after a minute.

Given time the device may get out of this state, but it is expected to timeout properly.

Device model: ESP_WROOM_32D (rev 1)

ESP-IDF Version: 3.3.1

Example Code:
  1. #include "nvs_flash.h"
  2. #include "lwip/err.h"
  3. #include "lwip/sockets.h"
  4. #include "lwip/sys.h"
  5. #include "lwip/netdb.h"
  6. #include "lwip/dns.h"
  7. #include "lwip/apps/sntp.h"
  8. #include "lwip/inet.h"
  9. #include "freertos/event_groups.h"
  10. #include "esp_err.h"
  11. #include "esp_log.h"
  12. #include "esp_wifi.h"
  13. #include "esp_event.h"
  14. #include "esp_event_loop.h"
  15. #include "esp_system.h"
  16. #include "esp_http_client.h"
  17. #include "esp_task_wdt.h"
  18. #include <tcpip_adapter.h>
  19. #include <string.h>
  20.  
  21. #define WIFI_CONNECT_TIMEOUT        20000/portTICK_PERIOD_MS
  22. #define WIFI_CONNECTED_BIT          BIT0
  23.  
  24. #define SSID                        "TESTWF"
  25. #define PASSWORD                    "testwfpw"
  26.  
  27. #define HTTP_DEFAULT_BUFFER_SIZE    16384
  28. #define HTTP_DEFAULT_TIMEOUT_MS     5000
  29. #define HTTP_DEFAULT_URL            "http://www.google.com"
  30.  
  31. #define HTTP_SAMPLE_DATA_SIZE       12800
  32.  
  33. esp_http_client_handle_t            client = NULL;
  34. EventGroupHandle_t                  wifi_event_group;
  35. char*                               TAG = "test_http";
  36.  
  37. esp_err_t wifi_event_handler(void *ctx, system_event_t *event) {
  38.     switch (event->event_id) {
  39.     case SYSTEM_EVENT_SCAN_DONE:
  40.         ESP_LOGI(TAG, "Wifi scan done.");
  41.         break;
  42.     case SYSTEM_EVENT_STA_START:
  43.         ESP_LOGI(TAG, "Wifi started.");
  44.         xEventGroupClearBits(wifi_event_group, WIFI_CONNECTED_BIT);
  45.         esp_wifi_connect();
  46.         break;
  47.     case SYSTEM_EVENT_STA_STOP:
  48.         ESP_LOGI(TAG, "Wifi stopped.");
  49.         break;
  50.     case SYSTEM_EVENT_STA_GOT_IP:
  51.         ESP_LOGI(TAG, "IP Obtained.");
  52.         xEventGroupSetBits(wifi_event_group, WIFI_CONNECTED_BIT);
  53.         break;
  54.     case SYSTEM_EVENT_STA_LOST_IP:
  55.         ESP_LOGI(TAG, "IP lost.");
  56.         break;
  57.     case SYSTEM_EVENT_STA_CONNECTED:
  58.         ESP_LOGI(TAG, "Wifi Connected.");
  59.         break;
  60.     case SYSTEM_EVENT_STA_DISCONNECTED:
  61.         ESP_LOGI(TAG, "Wifi disconnected. Reconnecting...");
  62.         esp_wifi_connect();
  63.         xEventGroupClearBits(wifi_event_group, WIFI_CONNECTED_BIT);
  64.         break;
  65.     case SYSTEM_EVENT_AP_START:
  66.         ESP_LOGI(TAG, "Access Point Started.");
  67.         break;
  68.     case SYSTEM_EVENT_AP_STOP:
  69.         ESP_LOGI(TAG, "Access Point Stopped.");
  70.         break;
  71.     case SYSTEM_EVENT_AP_STACONNECTED:
  72.         ESP_LOGI(TAG, "Device Connected to AP.");
  73.         break;
  74.     case SYSTEM_EVENT_AP_STADISCONNECTED:
  75.         ESP_LOGI(TAG, "Device Disconnected from AP.");
  76.         break;
  77.     case SYSTEM_EVENT_AP_PROBEREQRECVED:
  78.         ESP_LOGI(TAG, "Probe Request.");
  79.         break;
  80.     default:
  81.         ESP_LOGE(TAG, "ERROR: Unhandled Wi-Fi Event: %d", event->event_id);
  82.         break;
  83.     }
  84.     return ESP_OK;
  85. }
  86.  
  87. esp_err_t _http_event_handler(esp_http_client_event_t *evt) {
  88.     switch (evt->event_id) {
  89.     case HTTP_EVENT_ERROR:
  90.         ESP_LOGE(TAG, "HTTP_EVENT_ERROR");
  91.         break;
  92.     case HTTP_EVENT_ON_CONNECTED:
  93.         break;
  94.     case HTTP_EVENT_HEADER_SENT:
  95.         break;
  96.     case HTTP_EVENT_ON_HEADER:
  97.         ESP_LOGI(TAG, "HTTP_EVENT_ON_HEADER, key=%s, value=%s", evt->header_key, evt->header_value);
  98.         break;
  99.     case HTTP_EVENT_ON_DATA:
  100.         break;
  101.     case HTTP_EVENT_ON_FINISH:
  102.         break;
  103.     case HTTP_EVENT_DISCONNECTED:
  104.         break;
  105.     }
  106.     return ESP_OK;
  107. }
  108.  
  109. esp_err_t wifi_init(void) {
  110.     wifi_config_t sta_config;
  111.  
  112.     //init TCPIP, Event Group, and wifi.
  113.     tcpip_adapter_init();
  114.     wifi_event_group = xEventGroupCreate();
  115.     esp_event_loop_init(wifi_event_handler, NULL);;
  116.     wifi_init_config_t cfg = WIFI_INIT_CONFIG_DEFAULT();
  117.     esp_wifi_init(&cfg);
  118.     esp_wifi_set_storage(WIFI_STORAGE_FLASH);
  119.     esp_wifi_set_mode(WIFI_MODE_STA);
  120.     esp_wifi_set_ps(WIFI_PS_NONE);
  121.  
  122.     //init credentials
  123.     esp_wifi_get_config(WIFI_IF_STA, &sta_config);
  124.     sprintf((char*)sta_config.sta.ssid, SSID);
  125.     sprintf((char*)sta_config.sta.password, PASSWORD);
  126.     sta_config.sta.bssid_set = false;
  127.     esp_wifi_set_config(WIFI_IF_STA, &sta_config);
  128.  
  129.     //attempt to connect
  130.     ESP_LOGI(TAG, "Connecting to: ssid: %s\n", sta_config.sta.ssid);
  131.     esp_wifi_start();
  132.     if (strlen((char*)sta_config.sta.ssid) != 0) {
  133.         if (esp_wifi_connect() != ESP_OK) return ESP_FAIL;
  134.     }
  135.     else return ESP_ERR_WIFI_SSID;
  136.  
  137.     //wait for connection
  138.     xEventGroupWaitBits(wifi_event_group, WIFI_CONNECTED_BIT, false, true, WIFI_CONNECT_TIMEOUT);
  139.     if (xEventGroupGetBits(wifi_event_group) & WIFI_CONNECTED_BIT) {
  140.         return ESP_OK;
  141.     }
  142.  
  143.     return ESP_FAIL;
  144. }
  145.  
  146. esp_err_t wifi_http_init(uint16_t buffer_size, uint16_t timeout, char* url) {
  147.  
  148.     // config setup
  149.     if (client != NULL) return ESP_FAIL;
  150.     esp_http_client_config_t config;
  151.     memset(&config, 0, sizeof(esp_http_client_config_t));
  152.     config.url = url;
  153.     config.event_handler = _http_event_handler;
  154.     config.buffer_size = buffer_size;
  155.     config.timeout_ms = timeout;
  156.     client = esp_http_client_init(&config);
  157.     if (client == NULL) return ESP_FAIL;
  158.     else return ESP_OK;
  159. }
  160.  
  161. esp_err_t wifi_http_deinit(void) {
  162.     esp_err_t ret = esp_http_client_cleanup(client);
  163.     if (ret == ESP_OK) client = NULL;
  164.     return ret;
  165. }
  166.  
  167. esp_err_t wifi_http_close(void) {
  168.     return esp_http_client_close(client);
  169. }
  170.  
  171. esp_err_t wifi_http_post(char* url, char* post_data, int post_size, char** response, int* response_size) {
  172.     esp_err_t err = ESP_OK;
  173.     uint16_t resp_code = 0;
  174.  
  175.     *response_size = 0;
  176.  
  177.     if (client == NULL || url == NULL) {
  178.         ESP_LOGE(TAG, "ERROR: Invalid Parameters given to wifi_https_post.");
  179.         return ESP_ERR_INVALID_ARG;
  180.     }
  181.  
  182.     //set URL and HTTP method
  183.     esp_http_client_set_url(client, url);
  184.     esp_http_client_set_method(client, HTTP_METHOD_POST);
  185.  
  186.     // setup headers and other data
  187.     esp_http_client_set_post_field(client, post_data, post_size);
  188.  
  189.     // send post
  190.     err = esp_http_client_perform(client);
  191.  
  192.     if (err == ESP_OK) {
  193.         // allocate size of response
  194.         *response_size = esp_http_client_get_content_length(client);
  195.         *response = (char*)malloc(*response_size * sizeof(char) + 1);
  196.         memset(*response, 0, *response_size * sizeof(char) + 1);
  197.  
  198.         // retrieve and post response
  199.         if (esp_http_client_read(client, *response, *response_size) != -1) {
  200.  
  201.             // Check the Response Code
  202.             resp_code = esp_http_client_get_status_code(client);
  203.             ESP_LOGI(TAG, "HTTP POST Status = %d, content_length = %d", resp_code, *response_size);
  204.             if (resp_code != 200) {
  205.                 if (resp_code % 100 == 2) err = ESP_FAIL;
  206.                 else if (resp_code % 100 == 3) err = ESP_FAIL;
  207.                 else if (resp_code % 100 == 4) err = ESP_FAIL;
  208.                 else if (resp_code % 100 == 5) err = ESP_FAIL;
  209.             }
  210.         }
  211.         else {
  212.             ESP_LOGE(TAG, "HTTP POST request failed.");
  213.         }
  214.     }
  215.     else {
  216.         ESP_LOGE(TAG, "HTTP POST request failed: %s", esp_err_to_name(err));
  217.     }
  218.     return err;
  219. }
  220.  
  221. void task_time(void *pvParameters){
  222.     for (int i = 1; true; i++){
  223.         vTaskDelay(1000/portTICK_PERIOD_MS);
  224.         ESP_LOGI("Status", "%d seconds since startup.", i);
  225.     }
  226. }
  227.  
  228. void app_main(void) {
  229.     nvs_flash_init();
  230.  
  231.     char* data;
  232.     char* response = NULL;
  233.     int response_size = 0;
  234.     int fail_count = 0;
  235.  
  236.     data = (char*) malloc(HTTP_SAMPLE_DATA_SIZE*sizeof(char));
  237.     memset(data, 'a', HTTP_SAMPLE_DATA_SIZE);
  238.     data[HTTP_SAMPLE_DATA_SIZE-1] = 0;
  239.  
  240.     printf("\nTask Watchdog Enabled\n");
  241.     esp_task_wdt_init(60, true);
  242.     esp_task_wdt_reset();
  243.  
  244.     if (wifi_init() != ESP_OK) esp_restart();
  245.     xTaskCreatePinnedToCore(&task_time, "task_time", 4096, NULL, 10, NULL, 1);
  246.  
  247.     while(true){
  248.  
  249.         wifi_http_init(HTTP_DEFAULT_BUFFER_SIZE, HTTP_DEFAULT_TIMEOUT_MS, (char*) HTTP_DEFAULT_URL);
  250.         esp_task_wdt_reset();
  251.  
  252.         if (wifi_http_post((char*) HTTP_DEFAULT_URL, data, (HTTP_SAMPLE_DATA_SIZE - 1),&response, &response_size) != ESP_OK){
  253.             fail_count++;
  254.         }
  255.         if (fail_count > 10) break;
  256.  
  257.         if(response != NULL){
  258.             printf("Response: %s\n",response);
  259.             free(response);
  260.             response = NULL;
  261.         }
  262.         wifi_http_close();
  263.         vTaskDelay(1000/portTICK_PERIOD_MS);
  264.     }
  265.     esp_restart();
  266. }

In the example output below it shows the first two transmissions more or less failing properly, then on the third transmission it gets stuck after printing out the headers. I have also added a task to help show time elapsing after it gets stuck.

Output with Debug printout
  1. I (268) cpu_start: Pro cpu u
  2. p.
  3. I (269) cpu_start: Application information:
  4. I (269) cpu_start: Project name:     V2
  5. I (269) cpu_start: App version:      2f76511-dirty
  6. I (269) cpu_start: Compile time:     Jan 27 2020 10:23:00
  7. I (269) cpu_start: ELF file SHA256:  1b2e752ef3bbbe53...
  8. I (270) cpu_start: ESP-IDF:          v3.3.1-dirty
  9. I (270) cpu_start: Starting app cpu, entry point is 0x40080f8c
  10. 0x40080f8c: call_start_cpu1 at C:/msys32/home/bgoldbach/Git/esp-idf/components/esp32/cpu_start.c:269
  11.  
  12. I (254) cpu_start: App cpu up.
  13. D (271) memory_layout: Checking 7 reserved memory ranges:
  14. D (271) memory_layout: Reserved memory range 0x3ffae000 - 0x3ffae6e0
  15. D (271) memory_layout: Reserved memory range 0x3ffb0000 - 0x3ffb8768
  16. D (272) memory_layout: Reserved memory range 0x3ffe0000 - 0x3ffe0440
  17. D (272) memory_layout: Reserved memory range 0x3ffe3f20 - 0x3ffe4350
  18. D (272) memory_layout: Reserved memory range 0x40070000 - 0x40078000
  19. D (273) memory_layout: Reserved memory range 0x40078000 - 0x40080000
  20. 0x40080000: _WindowOverflow4 at C:/msys32/home/bgoldbach/Git/esp-idf/components/freertos/xtensa_vectors.S:1779
  21.  
  22. D (273) memory_layout: Reserved memory range 0x40080000 - 0x4008fc61
  23. 0x40080000: _WindowOverflow4 at C:/msys32/home/bgoldbach/Git/esp-idf/components/freertos/xtensa_vectors.S:1779
  24.  
  25. D (273) memory_layout: Building list of available memory regions:
  26. D (274) memory_layout: Available memory region 0x3ffae6e0 - 0x3ffb0000
  27. D (274) memory_layout: Available memory region 0x3ffb8768 - 0x3ffc0000
  28. D (274) memory_layout: Available memory region 0x3ffc0000 - 0x3ffc2000
  29. D (275) memory_layout: Available memory region 0x3ffc2000 - 0x3ffc4000
  30. D (275) memory_layout: Available memory region 0x3ffc4000 - 0x3ffc6000
  31. D (276) memory_layout: Available memory region 0x3ffc6000 - 0x3ffc8000
  32. D (276) memory_layout: Available memory region 0x3ffc8000 - 0x3ffca000
  33. D (276) memory_layout: Available memory region 0x3ffca000 - 0x3ffcc000
  34. D (277) memory_layout: Available memory region 0x3ffcc000 - 0x3ffce000
  35. D (277) memory_layout: Available memory region 0x3ffce000 - 0x3ffd0000
  36. D (278) memory_layout: Available memory region 0x3ffd0000 - 0x3ffd2000
  37. D (278) memory_layout: Available memory region 0x3ffd2000 - 0x3ffd4000
  38. D (278) memory_layout: Available memory region 0x3ffd4000 - 0x3ffd6000
  39. D (279) memory_layout: Available memory region 0x3ffd6000 - 0x3ffd8000
  40. D (279) memory_layout: Available memory region 0x3ffd8000 - 0x3ffda000
  41. D (279) memory_layout: Available memory region 0x3ffda000 - 0x3ffdc000
  42. D (280) memory_layout: Available memory region 0x3ffdc000 - 0x3ffde000
  43. D (280) memory_layout: Available memory region 0x3ffde000 - 0x3ffe0000
  44. D (281) memory_layout: Available memory region 0x3ffe0440 - 0x3ffe3f20
  45. D (281) memory_layout: Available memory region 0x3ffe4350 - 0x3ffe8000
  46. D (281) memory_layout: Available memory region 0x3ffe8000 - 0x3fff0000
  47. D (282) memory_layout: Available memory region 0x3fff0000 - 0x3fff8000
  48. D (282) memory_layout: Available memory region 0x3fff8000 - 0x3fffc000
  49. D (282) memory_layout: Available memory region 0x3fffc000 - 0x40000000
  50. D (283) memory_layout: Available memory region 0x4008fc64 - 0x40090000
  51. D (283) memory_layout: Available memory region 0x40090000 - 0x40092000
  52. D (284) memory_layout: Available memory region 0x40092000 - 0x40094000
  53. D (284) memory_layout: Available memory region 0x40094000 - 0x40096000
  54. D (284) memory_layout: Available memory region 0x40096000 - 0x40098000
  55. D (285) memory_layout: Available memory region 0x40098000 - 0x4009a000
  56. D (285) memory_layout: Available memory region 0x4009a000 - 0x4009c000
  57. D (286) memory_layout: Available memory region 0x4009c000 - 0x4009e000
  58. D (286) memory_layout: Available memory region 0x4009e000 - 0x400a0000
  59. I (286) heap_init: Initializing. RAM available for dynamic allocation:
  60. D (287) heap_init: New heap initialised at 0x3ffae6e0
  61. I (287) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
  62. D (287) heap_init: New heap initialised at 0x3ffb8768
  63. I (288) heap_init: At 3FFB8768 len 00027898 (158 KiB): DRAM
  64. I (288) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
  65. I (288) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
  66. D (289) heap_init: New heap initialised at 0x4008fc64
  67. I (289) heap_init: At 4008FC64 len 0001039C (64 KiB): IRAM
  68. I (289) cpu_start: Pro cpu start user code
  69. D (297) clk: RTC_SLOW_CLK calibration value: 3590605
  70. D (74) intr_alloc: Connected src 46 to int 2 (cpu 0)
  71. D (75) intr_alloc: Connected src 57 to int 3 (cpu 0)
  72. D (75) stack_chk: Intialize random stack guard
  73. D (76) intr_alloc: Connected src 24 to int 9 (cpu 0)
  74. I (77) cpu_start: Starting scheduler on PRO CPU.
  75. D (0) intr_alloc: Connected src 25 to int 2 (cpu 1)
  76. I (0) cpu_start: Starting scheduler on APP CPU.
  77. D (77) heap_init: New heap initialised at 0x3ffe0440
  78. D (77) heap_init: New heap initialised at 0x3ffe4350
  79. D (77) intr_alloc: Connected src 16 to int 12 (cpu 0)
  80. D (77) nvs: nvs_flash_init_custom partition=nvs start=9 count=4
  81.  
  82. Task Watchdog Enabled
  83. D (97) nvs: nvs_open_from_partition misc 1
  84. D (107) nvs: nvs_get_str_or_blob log
  85. D (107) nvs: nvs_erase_key log
  86.  
  87. D (107) nvs: nvs_get_str_or_blob log
  88. D (107) nvs: nvs_set_blob log 24
  89. I (117) wifi: wifi driver task: 3ffc3800, prio:23, stack:3584, core=1
  90. I (117) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
  91. D (117) efuse: coding scheme 0
  92. D (117) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 8 bit
  93. D (117) efuse: coding scheme 0
  94. D (117) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 0 bit
  95. D (117) efuse: coding scheme 0
  96. D (117) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 24 bit
  97. D (117) efuse: coding scheme 0
  98. D (117) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 16 bit
  99. D (117) efuse: coding scheme 0
  100. D (117) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 8 bit
  101. D (117) efuse: coding scheme 0
  102. D (117) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 0 bit
  103. D (117) efuse: coding scheme 0
  104. D (117) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 16 bit
  105. I (117) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
  106. D (117) efuse: coding scheme 0
  107. D (117) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 8 bit
  108. D (117) efuse: coding scheme 0
  109. D (117) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 0 bit
  110. D (117) efuse: coding scheme 0
  111. D (117) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 24 bit
  112. D (117) efuse: coding scheme 0
  113. D (117) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 16 bit
  114. D (117) efuse: coding scheme 0
  115. D (117) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 8 bit
  116. D (117) efuse: coding scheme 0
  117. D (117) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 0 bit
  118. D (117) efuse: coding scheme 0
  119. D (117) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 16 bit
  120. D (127) nvs: nvs_open_from_partition nvs.net80211 1
  121. D (127) nvs: nvs_get opmode 1
  122. D (127) nvs: nvs_get_str_or_blob sta.ssid
  123. D (127) nvs: nvs_get_str_or_blob sta.mac
  124. D (127) nvs: nvs_get sta.authmode 1
  125. D (127) nvs: nvs_get_str_or_blob sta.pswd
  126. D (127) nvs: nvs_get_str_or_blob sta.pmk
  127. D (127) nvs: nvs_get sta.chan 1
  128. D (127) nvs: nvs_get auto.conn 1
  129. D (127) nvs: nvs_get bssid.set 1
  130. D (127) nvs: nvs_get_str_or_blob sta.bssid
  131. D (127) nvs: nvs_get sta.lis_intval 2
  132. D (127) nvs: nvs_get sta.phym 1
  133. D (127) nvs: nvs_get sta.phybw 1
  134. D (127) nvs: nvs_get_str_or_blob sta.apsw
  135. D (127) nvs: nvs_get_str_or_blob sta.apinfo
  136. D (127) nvs: nvs_get sta.scan_method 1
  137. D (127) nvs: nvs_get sta.sort_method 1
  138. D (127) nvs: nvs_get sta.minrssi 1
  139. D (137) nvs: nvs_get sta.minauth 1
  140. D (137) nvs: nvs_get_str_or_blob ap.ssid
  141. D (137) nvs: nvs_get_str_or_blob ap.mac
  142. D (137) nvs: nvs_get_str_or_blob ap.passwd
  143. D (137) nvs: nvs_get_str_or_blob ap.pmk
  144. D (137) nvs: nvs_get ap.chan 1
  145. D (137) nvs: nvs_get ap.authmode 1
  146. D (137) nvs: nvs_get ap.hidden 1
  147. D (137) nvs: nvs_get ap.max.conn 1
  148. D (137) nvs: nvs_get bcn.interval 2
  149. D (137) nvs: nvs_get ap.phym 1
  150. D (137) nvs: nvs_get ap.phybw 1
  151. D (137) nvs: nvs_get ap.sndchan 1
  152. D (137) nvs: nvs_get lorate 1
  153. D (137) nvs: nvs_set_blob sta.mac 6
  154. D (137) nvs: nvs_set_blob ap.mac 6
  155. I (147) wifi: wifi firmware version: ac331d7
  156. I (147) wifi: config NVS flash: enabled
  157. I (147) wifi: config nano formating: disabled
  158. I (147) wifi: Init dynamic tx buffer num: 16
  159. I (147) wifi: Init data frame dynamic rx buffer num: 8
  160. I (147) wifi: Init management frame dynamic rx buffer num: 8
  161. I (147) wifi: Init management short buffer num: 32
  162. I (147) wifi: Init static rx buffer size: 1600
  163. I (147) wifi: Init static rx buffer num: 8
  164. I (147) wifi: Init dynamic rx buffer num: 8
  165. I (147) wifi: Set ps type: 0
  166.  
  167. I (147) test_http: Connecting to: ssid: TESTWF
  168.  
  169. D (147) RTC_MODULE: Wi-Fi takes adc2 lock.
  170. D (147) phy_init: loading PHY init data from application binary
  171. D (147) nvs: nvs_open_from_partition phy 0
  172. D (147) nvs: nvs_get cal_version 4
  173. D (147) nvs: nvs_get_str_or_blob cal_mac
  174. D (147) efuse: coding scheme 0
  175. D (147) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 8 bit
  176. D (147) efuse: coding scheme 0
  177. D (147) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 0 bit
  178. D (147) efuse: coding scheme 0
  179. D (147) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 24 bit
  180. D (147) efuse: coding scheme 0
  181. D (147) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 16 bit
  182. D (147) efuse: coding scheme 0
  183. D (147) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 8 bit
  184. D (147) efuse: coding scheme 0
  185. D (147) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 0 bit
  186. D (147) efuse: coding scheme 0
  187. D (147) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 16 bit
  188. D (157) nvs: nvs_get_str_or_blob cal_data
  189. D (157) nvs: nvs_close 3
  190. D (157) efuse: coding scheme 0
  191. D (157) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 8 bit
  192. D (157) efuse: coding scheme 0
  193. D (157) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 0 bit
  194. D (157) efuse: coding scheme 0
  195. D (157) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 24 bit
  196. D (157) efuse: coding scheme 0
  197. D (157) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 16 bit
  198. D (157) efuse: coding scheme 0
  199. D (157) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 8 bit
  200. D (157) efuse: coding scheme 0
  201. D (157) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 0 bit
  202. D (157) efuse: coding scheme 0
  203. D (157) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 16 bit
  204. I (247) phy: phy_version: 4102, 2fa7a43, Jul 15 2019, 13:06:06, 0, 0
  205. I (247) wifi: mode : sta (30:ae:a4:26:a7:04)
  206. D (247) event: SYSTEM_EVENT_STA_START
  207. I (247) test_http: Wifi started.
  208. I (2297) wifi: new:<5,0>, old:<1,0>, ap:<255,255>, sta:<5,0>, prof:1
  209. I (2307) wifi: state: init -> auth (b0)
  210. I (3307) wifi: state: auth -> init (200)
  211. I (3307) wifi: new:<5,0>, old:<5,0>, ap:<255,255>, sta:<5,0>, prof:1
  212. D (3307) event: SYSTEM_EVENT_STA_DISCONNECTED, ssid:TESTWF, ssid_len:6, bssid:24:f5:a2:04:0f:fb, reason:2,wifi reason: auth expire
  213. D (3307) tcpip_adapter: if0 start ip lost tmr: enter
  214. D (3307) tcpip_adapter: if0 start ip lost tmr: no need start because netif=0x3ffc7700 interval=120 ip=0
  215. I (3307) test_http: Wifi disconnected. Reconnecting...
  216. D (5357) event: SYSTEM_EVENT_STA_DISCONNECTED, ssid:TESTWF, ssid_len:6, bssid:00:00:00:00:00:00, reason:205,wifi reason: other reason
  217. D (5357) tcpip_adapter: if0 start ip lost tmr: enter
  218. D (5357) tcpip_adapter: if0 start ip lost tmr: no need start because netif=0x3ffc7700 interval=120 ip=0
  219. I (5357) test_http: Wifi disconnected. Reconnecting...
  220. I (7407) wifi: new:<5,0>, old:<5,0>, ap:<255,255>, sta:<5,0>, prof:1
  221. I (7407) wifi: state: init -> auth (b0)
  222. I (7447) wifi: state: auth -> assoc (0)
  223. I (7477) wifi: state: assoc -> run (10)
  224. I (9637) wifi: connected with TESTWF, aid = 1, channel 5, BW20, bssid = 24:f5:a2:04:0f:fb
  225. I (9637) wifi: security type: 3, phy: bgn, rssi: -78
  226. D (9637) nvs: nvs_set sta.chan 1 5
  227. D (9637) nvs: nvs_set_blob sta.apinfo 700
  228. I (9647) wifi: pm start, type: 0
  229.  
  230. D (9647) event: SYSTEM_EVENT_STA_CONNECTED, ssid:TESTWF, ssid_len:6, bssid:24:f5:a2:04:0f:fb, channel:5, authmode:3
  231. D (9647) tcpip_adapter: dhcp client init ip/mask/gw to all-0
  232. D (9647) tcpip_adapter: if0 start ip lost tmr: enter
  233. D (9647) tcpip_adapter: if0 start ip lost tmr: no need start because netif=0x3ffc7700 interval=120 ip=0
  234. D (9647) tcpip_adapter: dhcp client start successfully
  235. I (9647) test_http: Wifi Connected.
  236. I (9867) wifi: AP's beacon interval = 102400 us, DTIM period = 1
  237. D (10147) tcpip_adapter: if0 dhcpc cb
  238. D (10147) tcpip_adapter: if0 ip changed=1
  239. D (10147) event: SYSTEM_EVENT_STA_GOT_IP, ip:192.168.1.107, mask:255.255.255.0, gw:192.168.1.1
  240. I (10147) event: sta ip: 192.168.1.107, mask: 255.255.255.0, gw: 192.168.1.1
  241. I (10147) test_http: IP Obtained.
  242. D (10147) HTTP_CLIENT: set post file length = 12799
  243. D (10147) HTTP_CLIENT: Begin connect to: http://www.google.com:80
  244. D (10237) TRANS_TCP: [sock=48],connecting to server IP:64.233.177.106,Port:80...
  245. D (10267) HTTP_CLIENT: Write header[4]: POST / HTTP/1.1
  246. User-Agent: ESP32 HTTP Client/1.0
  247. Host: www.google.com
  248. Content-Type: application/x-www-form-urlencoded
  249. Content-Length: 12799
  250.  
  251.  
  252. I (11147) Status: 1 seconds since startup.
  253. E (11677) test_http: HTTP POST request failed: ESP_FAIL
  254. I (12147) Status: 2 seconds since startup.
  255. D (12677) HTTP_CLIENT: set post file length = 12799
  256. D (12677) HTTP_CLIENT: Begin connect to: http://www.google.com:80
  257. D (12677) TRANS_TCP: [sock=49],connecting to server IP:64.233.177.106,Port:80...
  258. D (12757) HTTP_CLIENT: Write header[4]: POST / HTTP/1.1
  259. User-Agent: ESP32 HTTP Client/1.0
  260. Host: www.google.com
  261. Content-Type: application/x-www-form-urlencoded
  262. Content-Length: 12799
  263.  
  264.  
  265. I (13147) Status: 3 seconds since startup.
  266. I (14147) Status: 4 seconds since startup.
  267. I (15147) Status: 5 seconds since startup.
  268. I (16147) Status: 6 seconds since startup.
  269. E (16867) test_http: HTTP POST request failed: ESP_FAIL
  270. I (17147) Status: 7 seconds since startup.
  271. D (17867) HTTP_CLIENT: set post file length = 12799
  272. D (17867) HTTP_CLIENT: Begin connect to: http://www.google.com:80
  273. D (17867) TRANS_TCP: [sock=50],connecting to server IP:64.233.177.106,Port:80...
  274. D (17877) HTTP_CLIENT: Write header[4]: POST / HTTP/1.1
  275. User-Agent: ESP32 HTTP Client/1.0
  276. Host: www.google.com
  277. Content-Type: application/x-www-form-urlencoded
  278. Content-Length: 12799
  279.  
  280.  
  281. I (18147) Status: 8 seconds since startup.
  282. I (19147) Status: 9 seconds since startup.
  283. I (20147) Status: 10 seconds since startup.
  284. I (21147) Status: 11 seconds since startup.
  285. I (22147) Status: 12 seconds since startup.
  286. I (23147) Status: 13 seconds since startup.
  287. I (24147) Status: 14 seconds since startup.
  288. I (25147) Status: 15 seconds since startup.
  289. I (26147) Status: 16 seconds since startup.
  290. I (27147) Status: 17 seconds since startup.
  291. I (28147) Status: 18 seconds since startup.
  292. I (29147) Status: 19 seconds since startup.
  293. I (30147) Status: 20 seconds since startup.
  294. I (31147) Status: 21 seconds since startup.
  295. I (32147) Status: 22 seconds since startup.
  296. I (33147) Status: 23 seconds since startup.
  297. I (34147) Status: 24 seconds since startup.
  298. I (35147) Status: 25 seconds since startup.
  299. I (36147) Status: 26 seconds since startup.
  300. I (37147) Status: 27 seconds since startup.
  301. I (38147) Status: 28 seconds since startup.
  302. I (39147) Status: 29 seconds since startup.
  303. I (40147) Status: 30 seconds since startup.
  304. I (41147) Status: 31 seconds since startup.
  305. I (42147) Status: 32 seconds since startup.
  306. I (43147) Status: 33 seconds since startup.
  307. I (44147) Status: 34 seconds since startup.
  308. I (45147) Status: 35 seconds since startup.
  309. I (46147) Status: 36 seconds since startup.
  310. I (47147) Status: 37 seconds since startup.
  311. I (48147) Status: 38 seconds since startup.
  312. I (49147) Status: 39 seconds since startup.
  313. I (50147) Status: 40 seconds since startup.
  314. I (51147) Status: 41 seconds since startup.
  315. I (52147) Status: 42 seconds since startup.
  316. I (53147) Status: 43 seconds since startup.
  317. I (54147) Status: 44 seconds since startup.
  318. I (55147) Status: 45 seconds since startup.
  319. I (56147) Status: 46 seconds since startup.
  320. I (57147) Status: 47 seconds since startup.
  321. I (58147) Status: 48 seconds since startup.
  322. I (59147) Status: 49 seconds since startup.
  323. I (60147) Status: 50 seconds since startup.
  324. I (61147) Status: 51 seconds since startup.
  325. I (62147) Status: 52 seconds since startup.
  326. I (63147) Status: 53 seconds since startup.
  327. I (64147) Status: 54 seconds since startup.
  328. I (65147) Status: 55 seconds since startup.
  329. I (66147) Status: 56 seconds since startup.
  330. I (67147) Status: 57 seconds since startup.
  331. I (68147) Status: 58 seconds since startup.
  332. I (69147) Status: 59 seconds since startup.
  333. I (70147) Status: 60 seconds since startup.
  334. I (71147) Status: 61 seconds since startup.
  335. I (72147) Status: 62 seconds since startup.
  336. I (73147) Status: 63 seconds since startup.
  337. I (74147) Status: 64 seconds since startup.
  338. I (75147) Status: 65 seconds since startup.
  339. I (76147) Status: 66 seconds since startup.
  340. I (77147) Status: 67 seconds since startup.
  341. I (78147) Status: 68 seconds since startup.
  342. I (79147) Status: 69 seconds since startup.

Re: esp_http_client post failing to timeout in bad Wi-Fi

Posted: Thu Jan 30, 2020 4:28 pm
by BrettG
I have tried using the esp_http_client_fetch_headers fix that was implemented in esp-idf 4.0rc and it reduced the issue slightly but is still occurring.

my understanding is that the timeout currently is set up to be the timeout for each small action of the larger transaction, rather than being the timeout for the transaction as a whole. unfortunately that does not work well for my purposes.

I have also tried using the is_async flag the client init with slight success. With the ability to call esp_http_client_perform asynchronously i can time it out manually, but it appears that after the first transaction the esp-tls is left in a bad state and all transactions afterwards using the same client handle fails with the message "esp-tls: invalid esp-tls state".

I am continuing to look into running esp_http_client_perform asynchronously and how to leave esp-tls in a usable state.