Add error handling w/temp debug logs

ports/esp32s2/common-hal/socketpool/Socket.c

@@ -26,8 +26,13 @@
 
 #include "shared-bindings/socketpool/Socket.h"
 
+#include "lib/utils/interrupt_char.h"
 #include "py/mperrno.h"
 #include "py/runtime.h"
+#include "supervisor/shared/tick.h"
+
+#include "esp_log.h"
+static const char* TAG = "socket";
 
 void common_hal_socketpool_socket_settimeout(socketpool_socket_obj_t* self, mp_uint_t timeout_ms) {
     self->timeout_ms = timeout_ms;
@@ -43,13 +48,15 @@ bool common_hal_socketpool_socket_connect(socketpool_socket_obj_t* self, const c
         tls_config = &self->ssl_context->ssl_config;
     }
     int result = esp_tls_conn_new_sync(host, hostlen, port, tls_config, self->tcp);
+    ESP_EARLY_LOGW(TAG, "connect result %d", result);
     self->connected = result >= 0;
     if (result < 0) {
         int esp_tls_code;
-        esp_tls_get_and_clear_last_error(self->tcp->error_handle, &esp_tls_code, NULL);
+        int flags;
+        esp_err_t err = esp_tls_get_and_clear_last_error(self->tcp->error_handle, &esp_tls_code, &flags);
 
         // mp_raise_espidf_MemoryError
-        mp_raise_OSError_msg_varg(translate("Unhandled ESP TLS error %d"), esp_tls_code);
+        mp_raise_OSError_msg_varg(translate("Unhandled ESP TLS error %d %d %x"), esp_tls_code, flags, err);
     }
     return self->connected;
 }
@@ -68,19 +75,44 @@ mp_uint_t common_hal_socketpool_socket_send(socketpool_socket_obj_t* self, const
 }
 
 mp_uint_t common_hal_socketpool_socket_recv_into(socketpool_socket_obj_t* self, const uint8_t* buf, mp_uint_t len) {
-    size_t received = esp_tls_conn_read(self->tcp, (void*) buf, len);
+    size_t received = 0;
+    ssize_t last_read = 1;
+    uint64_t start_ticks = supervisor_ticks_ms64();
+    while (received < len &&
+           last_read > 0 &&
+           (self->timeout_ms == 0 || supervisor_ticks_ms64() - start_ticks <= self->timeout_ms) &&
+           !mp_hal_is_interrupted()) {
+        RUN_BACKGROUND_TASKS;
+        size_t available = esp_tls_get_bytes_avail(self->tcp);
+        ESP_EARLY_LOGW(TAG, "available %d", available);
+        size_t remaining = len - received;
+        if (available > remaining) {
+            available = remaining;
+        }
+        if (true || available > 0) {
+            if (available == 0) {
+                available = len - received;
+            }
+            last_read = esp_tls_conn_read(self->tcp, (void*) buf + received, available);
+            ESP_EARLY_LOGW(TAG, "read %d out of %d", last_read, available);
+            received += last_read;
+        }
+    }
 
-    if (received == 0) {
+    if (last_read == 0) {
         // socket closed
+        ESP_EARLY_LOGW(TAG, "receive close %d %d", received, len);
         common_hal_socketpool_socket_close(self);
     }
-    if (received < 0) {
+    if (last_read < 0) {
+        // ESP_EARLY_LOGI(TAG, "received %d", received);
         mp_raise_BrokenPipeError();
     }
     return received;
 }
 
 void common_hal_socketpool_socket_close(socketpool_socket_obj_t* self) {
+    // ESP_EARLY_LOGW(TAG, "close");
     if (self->connected) {
         self->connected = false;
     }
@@ -95,5 +127,6 @@ void common_hal_socketpool_socket_close(socketpool_socket_obj_t* self) {
 }
 
 bool common_hal_socketpool_socket_get_closed(socketpool_socket_obj_t* self) {
+    // ESP_EARLY_LOGW(TAG, "tcp %p", self->tcp);
     return self->tcp == NULL;
 }

ports/esp32s2/common-hal/wifi/Radio.c

@@ -38,6 +38,9 @@
 #include "esp-idf/components/esp_wifi/include/esp_wifi.h"
 #include "esp-idf/components/lwip/include/apps/ping/ping_sock.h"
 
+#include "esp_log.h"
+static const char* TAG = "radio";
+
 static void start_station(wifi_radio_obj_t *self) {
     if (self->sta_mode) {
         return;
@@ -160,6 +163,8 @@ mp_int_t common_hal_wifi_radio_ping(wifi_radio_obj_t *self, mp_obj_t ip_address,
     uint32_t elapsed_time = 0xffffffff;
     if (received > 0) {
         esp_ping_get_profile(ping, ESP_PING_PROF_TIMEGAP, &elapsed_time, sizeof(elapsed_time));
+    } else {
+        ESP_EARLY_LOGW(TAG, "received none - time %d timeout %d", total_time_ms, timeout_ms);
     }
     esp_ping_delete_session(ping);
 

ports/esp32s2/common-hal/wifi/__init__.c

@@ -37,6 +37,9 @@
 
 wifi_radio_obj_t common_hal_wifi_radio_obj;
 
+#include "esp_log.h"
+static const char* TAG = "wifi";
+
 static void event_handler(void* arg, esp_event_base_t event_base,
                           int32_t event_id, void* event_data) {
     wifi_radio_obj_t* radio = arg;
@@ -46,11 +49,15 @@ static void event_handler(void* arg, esp_event_base_t event_base,
         } else if (event_id == WIFI_EVENT_STA_START) {
         } else if (event_id == WIFI_EVENT_STA_STOP) {
         } else if (event_id == WIFI_EVENT_STA_CONNECTED) {
+            ESP_EARLY_LOGW(TAG, "connected");
         } else if (event_id == WIFI_EVENT_STA_DISCONNECTED) {
-            // wifi_event_sta_disconnected_t* d = (wifi_event_sta_disconnected_t*) event_data;
+            ESP_EARLY_LOGW(TAG, "disconnected");
-            if (event_id != WIFI_REASON_ASSOC_LEAVE) {
+            wifi_event_sta_disconnected_t* d = (wifi_event_sta_disconnected_t*) event_data;
+            uint8_t reason = d->reason;
+            if (reason != WIFI_REASON_ASSOC_LEAVE) {
                 // reconnect
             }
+            ESP_EARLY_LOGW(TAG, "reason %d 0x%02x", reason, reason);
             xEventGroupSetBits(radio->event_group_handle, WIFI_DISCONNECTED_BIT);
         } else if (event_id == WIFI_EVENT_STA_AUTHMODE_CHANGE) {
         }
@@ -70,6 +77,7 @@ static void event_handler(void* arg, esp_event_base_t event_base,
     //     ESP_LOGI(TAG,"connect to the AP fail");
     // } else
     if (event_base == IP_EVENT && event_id == IP_EVENT_STA_GOT_IP) {
+        ESP_EARLY_LOGW(TAG, "got ip");
         xEventGroupSetBits(radio->event_group_handle, WIFI_CONNECTED_BIT);
     }
 }

shared-bindings/socketpool/Socket.c

@@ -36,6 +36,9 @@
 #include "py/runtime.h"
 #include "py/mperrno.h"
 
+#include "esp_log.h"
+static const char* TAG = "socket binding";
+
 //| class Socket:
 //|     """TCP, UDP and RAW socket. Cannot be created directly. Instead, call
 //|        `SocketPool.socket()`.
@@ -180,6 +183,7 @@ STATIC mp_obj_t socketpool_socket_connect(mp_obj_t self_in, mp_obj_t addr_in) {
 
     bool ok = common_hal_socketpool_socket_connect(self, host, hostlen, port);
     if (!ok) {
+        ESP_EARLY_LOGW(TAG, "socket connect failed");
         mp_raise_OSError(0);
     }
 
@@ -262,6 +266,11 @@ STATIC mp_obj_t socketpool_socket_recv_into(size_t n_args, const mp_obj_t *args)
         }
     }
 
+    if (len == 0) {
+        ESP_EARLY_LOGW(TAG, "len 0");
+        mp_raise_OSError(0);
+    }
+
     mp_int_t ret = common_hal_socketpool_socket_recv_into(self, (byte*)bufinfo.buf, len);
     return mp_obj_new_int_from_uint(ret);
 }

shared-bindings/socketpool/SocketPool.c

@@ -37,6 +37,9 @@
 #include "shared-bindings/socketpool/Socket.h"
 #include "shared-bindings/socketpool/SocketPool.h"
 
+#include "esp_log.h"
+static const char* TAG = "socketpool binding";
+
 //| class SocketPool:
 //|     """A pool of socket resources available for the given radio. Only one
 //|        SocketPool can be created for each radio.
@@ -119,6 +122,7 @@ STATIC mp_obj_t socketpool_socketpool_getaddrinfo(size_t n_args, const mp_obj_t
     }
 
     if (ip_str == mp_const_none) {
+        ESP_EARLY_LOGW(TAG, "no ip str");
         mp_raise_OSError(0);
     }
 

shared-bindings/wifi/Radio.c

@@ -159,7 +159,8 @@ const mp_obj_property_t wifi_radio_ipv4_address_obj = {
 };
 
 //|     def ping(self, ip, *, timeout: float = 0.5) -> float:
-//|         """Ping an IP to test connectivity. Returns echo time in seconds."""
+//|         """Ping an IP to test connectivity. Returns echo time in seconds.
+//|            Returns None when it times out."""
 //|         ...
 //|
 STATIC mp_obj_t wifi_radio_ping(size_t n_args, const mp_obj_t *pos_args, mp_map_t *kw_args) {
@@ -179,6 +180,9 @@ STATIC mp_obj_t wifi_radio_ping(size_t n_args, const mp_obj_t *pos_args, mp_map_
     }
 
     mp_int_t time_ms = common_hal_wifi_radio_ping(self, args[ARG_ip].u_obj, timeout);
+    if (time_ms == -1) {
+        return mp_const_none;
+    }
 
     return mp_obj_new_float(time_ms / 1000.0);
 }