From 80b15f6b3b8bc513e8edcec48a0c97205be27fd3 Mon Sep 17 00:00:00 2001 From: Scott Shawcroft Date: Wed, 19 Aug 2020 17:51:33 -0700 Subject: [PATCH] Add error handling w/temp debug logs --- ports/esp32s2/common-hal/socketpool/Socket.c | 43 +++++++++++++++++--- ports/esp32s2/common-hal/wifi/Radio.c | 5 +++ ports/esp32s2/common-hal/wifi/__init__.c | 12 +++++- shared-bindings/socketpool/Socket.c | 9 ++++ shared-bindings/socketpool/SocketPool.c | 4 ++ shared-bindings/wifi/Radio.c | 6 ++- 6 files changed, 71 insertions(+), 8 deletions(-) diff --git a/ports/esp32s2/common-hal/socketpool/Socket.c b/ports/esp32s2/common-hal/socketpool/Socket.c index 36018b3d14..074d9885f3 100644 --- a/ports/esp32s2/common-hal/socketpool/Socket.c +++ b/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; } diff --git a/ports/esp32s2/common-hal/wifi/Radio.c b/ports/esp32s2/common-hal/wifi/Radio.c index 0f97565da0..be8e7e6d9f 100644 --- a/ports/esp32s2/common-hal/wifi/Radio.c +++ b/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); diff --git a/ports/esp32s2/common-hal/wifi/__init__.c b/ports/esp32s2/common-hal/wifi/__init__.c index 95b182288e..f845e092fc 100644 --- a/ports/esp32s2/common-hal/wifi/__init__.c +++ b/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; - if (event_id != WIFI_REASON_ASSOC_LEAVE) { + ESP_EARLY_LOGW(TAG, "disconnected"); + 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); } } diff --git a/shared-bindings/socketpool/Socket.c b/shared-bindings/socketpool/Socket.c index ddead95078..932e8e856c 100644 --- a/shared-bindings/socketpool/Socket.c +++ b/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); } diff --git a/shared-bindings/socketpool/SocketPool.c b/shared-bindings/socketpool/SocketPool.c index f8812f61f1..579a4824c8 100644 --- a/shared-bindings/socketpool/SocketPool.c +++ b/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); } diff --git a/shared-bindings/wifi/Radio.c b/shared-bindings/wifi/Radio.c index 260a280c2b..6fd0c33744 100644 --- a/shared-bindings/wifi/Radio.c +++ b/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); }