ESP32 - Concurrent socket MQTT + TCP

[Marc-Aurele]

Hello

When I'm using MQTT only, all is working fine. But when I want to open a additional TCP socket (just a TCP while I'm already connected with MQTT), I can connect and send some data but after a while, my tcp sending function returns -1 continuously (errno = 11 : EWOULDBLOCK or EAGAIN) (this line => int written = send(sock, data + (len - to_write), to_write, 0)):

Code: Select all

static int socket_send(const char *tag, const int sock, const char * data, const size_t len){
    int to_write = len;
    int error_cnt = 0;
    while (to_write > 0) {
        int written = send(sock, data + (len - to_write), to_write, 0);
        if (written < 0 && errno != EINPROGRESS && errno != EAGAIN && errno != EWOULDBLOCK) {
            log_socket_error(tag, sock, errno, "Error occurred during sending");
            printf("socket_send TIMEOUT %d\r\n",errno);
            return -1;
        } else if (written < 0) {
            printf("written %d %d\r\n",written,errno);
            vTaskDelay(pdMS_TO_TICKS(YIELD_TO_ALL_MS));
            error_cnt++;
            if (error_cnt >= 50) {
                printf("socket_send TIMEOUT %d\r\n",error_cnt);
                return -1;
            }
            //printf("error_cnt %d\r\n",error_cnt);
        } else {
            to_write -= written;
            error_cnt = 0;
        }
    }
    return len;
}

At first, I thought it was a concurrent access between the MQTT task and my TCP task, So I tried to change priority but without any success.

Has anyone seen this before. Feel free to share any suggestion.

Thank you in advance

Best regards,

Aurélien

[Sprite]

That is typically expected behaviour, but specifically for a socket that is opened in non-blocking mode. You seem to expect your socket to react like it is in blocking mode. How do you open that socket, can you post code for that?

[Marc-Aurele]

Hello,

Thank you for the reply.
Indeed, my tcp socket seems to be configured in non blocking mode :

Code: Select all

 
    // Marking the socket as non-blocking
    int flags = fcntl(sock, F_GETFL);
    if (fcntl(sock, F_SETFL, flags | O_NONBLOCK) == -1) {
        log_socket_error(TAG, sock, errno, "Unable to set socket non blocking");
    }

Here is the entire code of my connection function :

Code: Select all

uint32_t tcp_client_connect(char* p_tcp_server, char* p_tcp_port) {

    struct addrinfo hints = { .ai_socktype = SOCK_STREAM };

    if (m_socket != INVALID_SOCK)
        return 0;

    int res = getaddrinfo(p_tcp_server, p_tcp_port, &hints, &m_addressInfo);
    if (res != 0 || m_addressInfo == NULL) {
        ESP_LOGE(TAG, "couldn't get hostname for `%s` "
                      "getaddrinfo() returns %d, addrinfo=%p", p_tcp_server, res, m_addressInfo);
        goto error;
    }

    // Creating client's socket
    m_socket = socket(m_addressInfo->ai_family, m_addressInfo->ai_socktype, m_addressInfo->ai_protocol);
    if (m_socket < 0) {
        log_socket_error(TAG, m_socket, errno, "Unable to create socket");
        goto error;
    }
    ESP_LOGI(TAG, "Socket created, connecting to %s:%s", p_tcp_server, p_tcp_port);

    // Marking the socket as non-blocking
    int flags = fcntl(m_socket, F_GETFL);
    if (fcntl(m_socket, F_SETFL, flags | O_NONBLOCK) == -1) {
        log_socket_error(TAG, m_socket, errno, "Unable to set socket non blocking");
    }

    if (connect(m_socket, m_addressInfo->ai_addr, m_addressInfo->ai_addrlen) != 0) {
        if (errno == EINPROGRESS) {
            ESP_LOGD(TAG, "connection in progress");
            fd_set fdset;
            FD_ZERO(&fdset);
            FD_SET(m_socket, &fdset);

            // Connection in progress -> have to wait until the connecting socket is marked as writable, i.e. connection completes
            res = select(m_socket+1, NULL, &fdset, NULL, NULL);
            if (res < 0) {
                log_socket_error(TAG, m_socket, errno, "Error during connection: select for socket to be writable");
                goto error;
            } else if (res == 0) {
                log_socket_error(TAG, m_socket, errno, "Connection timeout: select for socket to be writable");
                goto error;
            } else {
                int sockerr;
                socklen_t len = (socklen_t)sizeof(int);

                if (getsockopt(m_socket, SOL_SOCKET, SO_ERROR, (void*)(&sockerr), &len) < 0) {
                    log_socket_error(TAG, m_socket, errno, "Error when getting socket error using getsockopt()");
                    goto error;
                }
                if (sockerr) {
                    log_socket_error(TAG, m_socket, sockerr, "Connection error");
                    goto error;
                }
            }
        } else {
            log_socket_error(TAG, m_socket, errno, "Socket is unable to connect");
            goto error;
        }
    }

    return 0;

error:
    if (m_socket != INVALID_SOCK) {
        close(m_socket);
        m_socket = INVALID_SOCK;
    }
    free(m_addressInfo);
    return 1;
}

[Marc-Aurele]

Here is the send function :

Code: Select all

static int socket_send(const char *tag, const int sock, const char * data, const size_t len){
    int to_write = len;
    int error_cnt = 0;
    while (to_write > 0) {
        int written = send(sock, data + (len - to_write), to_write, 0);
        if (written < 0 && errno != EINPROGRESS && errno != EAGAIN && errno != EWOULDBLOCK) {
            log_socket_error(tag, sock, errno, "Error occurred during sending");
            printf("socket_send TIMEOUT %d\r\n",errno);
            return -1;
        } else if (written < 0) {
            printf("written %d %d\r\n",written,errno);
            vTaskDelay(pdMS_TO_TICKS(YIELD_TO_ALL_MS));
            error_cnt++;
            if (error_cnt >= 50) {
                printf("socket_send TIMEOUT %d\r\n",error_cnt);
                return -1;
            }
            //printf("error_cnt %d\r\n",error_cnt);
        } else {
            to_write -= written;
            error_cnt = 0;
        }
    }
    return len;
}

What I don't understand is that I have a "vTaskDelay" when an EWOULDBLOCK or EAGAIN is raised, so it should let the previous buffer to be sent ? And next retry should succeed ... but it doesn't !

[Marc-Aurele]

Here is some log when the issue occurs (with LWIP debug activated)

Code: Untitled.txt Select all

[22:13:51:499] <0x1b>[0;32mI (34566) TCP_IP: Client sends data to the server...<0x1b>[0m␍␊

[22:13:51:505] lwip_send(60, data=0x3fc97168, size=600, flags=0x0)␍␊

[22:13:51:510] lwip_send(60) err=0 written=600␍␊

[22:13:51:510] <0x1b>[0;32mI (34576) TCP_IP: Written: 600<0x1b>[0m␍␊

[22:13:51:515] <0x1b>[0;32mI (34576) NimBLE: GATT procedure initiated: write; <0x1b>[0m␍␊

[22:13:51:521] <0x1b>[0;32mI (34586) NimBLE: att_handle=60 len=3␍␊

[22:13:51:524] <0x1b>[0m␍␊

[22:13:51:601] <0x1b>[0;32mI (34676) NimBLE: Write complete; status=0 conn_handle=2 attr_handle=60␍␊

[22:13:51:606] <0x1b>[0m␍␊

[22:13:51:606] data_sent 600␍␍␊

[22:13:51:606] data_sent 600␍␍␊

[22:13:51:606] <0x1b>[0;32mI (34686) NimBLE: GATT procedure initiated: write; <0x1b>[0m␍␊

[22:13:51:618] <0x1b>[0;32mI (34686) NimBLE: att_handle=60 len=3␍␊

[22:13:51:618] <0x1b>[0m␍␊

[22:13:51:649] lwip_select: timeout expired␍␊

[22:13:51:649] lwip_select(60, 0x3fcd56c0, 0x0, 0x3fcd56c8, tvsec=0 tvusec=0)␍␊

[22:13:51:659] lwip_select: no timeout, returning 0␍␊

[22:13:51:659] lwip_select(60, 0x3fcd5730, 0x0, 0x3fcd5738, tvsec=1 tvusec=0)␍␊

[22:13:51:701] <0x1b>[0;32mI (34776) NimBLE: Write complete; status=0 conn_handle=2 attr_handle=60␍␊

[22:13:51:706] <0x1b>[0m␍␊

[22:13:51:706] <0x1b>[0;32mI (34776) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=180␍␊

[22:13:51:713] <0x1b>[0m␍␊

[22:13:51:713] <0x1b>[0;32mI (34776) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=180␍␊

[22:13:51:723] <0x1b>[0m␍␊

[22:13:51:723] <0x1b>[0;32mI (34786) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=180␍␊

[22:13:51:730] <0x1b>[0m␍␊

[22:13:51:730] <0x1b>[0;32mI (34796) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=60␍␊

[22:13:51:740] <0x1b>[0m␍␊

[22:13:51:740] <0x1b>[0;32mI (34806) NimBLE: received notification; conn_handle=2 attr_handle=65 attr_len=1␍␊

[22:13:51:745] <0x1b>[0m␍␊

[22:13:51:745] m_data_buffer_len 600␍␍␊

[22:13:51:750] <0x1b>[0;32mI (34816) TCP_IP: Client sends data to the server...<0x1b>[0m␍␊

[22:13:51:756] lwip_send(60, data=0x3fc97168, size=600, flags=0x0)␍␊

[22:13:51:762] lwip_send(60) err=0 written=600␍␊

[22:13:51:762] <0x1b>[0;32mI (34826) TCP_IP: Written: 600<0x1b>[0m␍␊

[22:13:51:767] <0x1b>[0;32mI (34826) NimBLE: GATT procedure initiated: write; <0x1b>[0m␍␊

[22:13:51:773] <0x1b>[0;32mI (34836) NimBLE: att_handle=60 len=3␍␊

[22:13:51:776] <0x1b>[0m␍␊

[22:13:51:851] <0x1b>[0;32mI (34926) NimBLE: Write complete; status=0 conn_handle=2 attr_handle=60␍␊

[22:13:51:856] <0x1b>[0m␍␊

[22:13:51:856] data_sent 1200␍␍␊

[22:13:51:856] data_sent 1200␍␍␊

[22:13:51:856] <0x1b>[0;32mI (34936) NimBLE: GATT procedure initiated: write; <0x1b>[0m␍␊

[22:13:51:869] <0x1b>[0;32mI (34936) NimBLE: att_handle=60 len=3␍␊

[22:13:51:869] <0x1b>[0m␍␊

[22:13:52:001] <0x1b>[0;32mI (35076) NimBLE: Write complete; status=0 conn_handle=2 attr_handle=60␍␊

[22:13:52:006] <0x1b>[0m␍␊

[22:13:52:006] <0x1b>[0;32mI (35076) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=180␍␊

[22:13:52:017] <0x1b>[0m␍␊

[22:13:52:017] <0x1b>[0;32mI (35076) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=180␍␊

[22:13:52:028] <0x1b>[0m␍␊

[22:13:52:028] <0x1b>[0;32mI (35086) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=180␍␊

[22:13:52:028] <0x1b>[0m␍␊

[22:13:52:028] <0x1b>[0;32mI (35096) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=60␍␊

[22:13:52:041] <0x1b>[0m␍␊

[22:13:52:041] <0x1b>[0;32mI (35106) NimBLE: received notification; conn_handle=2 attr_handle=65 attr_len=1␍␊

[22:13:52:050] <0x1b>[0m␍␊

[22:13:52:050] m_data_buffer_len 600␍␍␊

[22:13:52:055] <0x1b>[0;32mI (35116) TCP_IP: Client sends data to the server...<0x1b>[0m␍␊

[22:13:52:059] lwip_send(60, data=0x3fc97168, size=600, flags=0x0)␍␊

[22:13:52:063] lwip_send(60) err=0 written=600␍␊

[22:13:52:063] <0x1b>[0;32mI (35126) TCP_IP: Written: 600<0x1b>[0m␍␊

[22:13:52:067] <0x1b>[0;32mI (35126) NimBLE: GATT procedure initiated: write; <0x1b>[0m␍␊

[22:13:52:073] <0x1b>[0;32mI (35136) NimBLE: att_handle=60 len=3␍␊

[22:13:52:076] <0x1b>[0m␍␊

[22:13:52:201] <0x1b>[0;32mI (35276) NimBLE: Write complete; status=0 conn_handle=2 attr_handle=60␍␊

[22:13:52:206] <0x1b>[0m␍␊

[22:13:52:206] data_sent 1800␍␍␊

[22:13:52:206] data_sent 1800␍␍␊

[22:13:52:206] <0x1b>[0;32mI (35286) NimBLE: GATT procedure initiated: write; <0x1b>[0m␍␊

[22:13:52:218] <0x1b>[0;32mI (35286) NimBLE: att_handle=60 len=3␍␊

[22:13:52:218] <0x1b>[0m␍␊

[22:13:52:301] <0x1b>[0;32mI (35376) NimBLE: Write complete; status=0 conn_handle=2 attr_handle=60␍␊

[22:13:52:306] <0x1b>[0m␍␊

[22:13:52:306] <0x1b>[0;32mI (35376) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=180␍␊

[22:13:52:317] <0x1b>[0m␍␊

[22:13:52:317] <0x1b>[0;32mI (35376) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=180␍␊

[22:13:52:328] <0x1b>[0m␍␊

[22:13:52:328] <0x1b>[0;32mI (35386) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=180␍␊

[22:13:52:328] <0x1b>[0m␍␊

[22:13:52:328] <0x1b>[0;32mI (35396) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=60␍␊

[22:13:52:340] <0x1b>[0m␍␊

[22:13:52:340] <0x1b>[0;32mI (35406) NimBLE: received notification; conn_handle=2 attr_handle=65 attr_len=1␍␊

[22:13:52:347] <0x1b>[0m␍␊

[22:13:52:347] m_data_buffer_len 600␍␍␊

[22:13:52:352] <0x1b>[0;32mI (35416) TCP_IP: Client sends data to the server...<0x1b>[0m␍␊

[22:13:52:356] lwip_send(60, data=0x3fc97168, size=600, flags=0x0)␍␊

[22:13:52:362] lwip_send(60) err=0 written=600␍␊

[22:13:52:362] <0x1b>[0;32mI (35426) TCP_IP: Written: 600<0x1b>[0m␍␊

[22:13:52:367] <0x1b>[0;32mI (35426) NimBLE: GATT procedure initiated: write; <0x1b>[0m␍␊

[22:13:52:373] <0x1b>[0;32mI (35436) NimBLE: att_handle=60 len=3␍␊

[22:13:52:375] <0x1b>[0m␍␊

[22:13:52:451] <0x1b>[0;32mI (35526) NimBLE: Write complete; status=0 conn_handle=2 attr_handle=60␍␊

[22:13:52:456] <0x1b>[0m␍␊

[22:13:52:456] data_sent 2400␍␍␊

[22:13:52:456] data_sent 2400␍␍␊

[22:13:52:456] <0x1b>[0;32mI (35536) NimBLE: GATT procedure initiated: write; <0x1b>[0m␍␊

[22:13:52:468] <0x1b>[0;32mI (35536) NimBLE: att_handle=60 len=3␍␊

[22:13:52:468] <0x1b>[0m␍␊

[22:13:52:551] <0x1b>[0;32mI (35626) NimBLE: Write complete; status=0 conn_handle=2 attr_handle=60␍␊

[22:13:52:556] <0x1b>[0m␍␊

[22:13:52:556] <0x1b>[0;32mI (35626) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=180␍␊

[22:13:52:567] <0x1b>[0m␍␊

[22:13:52:567] <0x1b>[0;32mI (35626) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=180␍␊

[22:13:52:578] <0x1b>[0m␍␊

[22:13:52:578] <0x1b>[0;32mI (35636) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=180␍␊

[22:13:52:578] <0x1b>[0m␍␊

[22:13:52:578] <0x1b>[0;32mI (35646) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=60␍␊

[22:13:52:590] <0x1b>[0m␍␊

[22:13:52:600] <0x1b>[0;32mI (35676) NimBLE: received notification; conn_handle=2 attr_handle=65 attr_len=1␍␊

[22:13:52:606] <0x1b>[0m␍␊

[22:13:52:606] m_data_buffer_len 600␍␍␊

[22:13:52:606] <0x1b>[0;32mI (35676) TCP_IP: Client sends data to the server...<0x1b>[0m␍␊

[22:13:52:611] lwip_send(60, data=0x3fc97168, size=600, flags=0x0)␍␊

[22:13:52:617] lwip_send(60) err=0 written=600␍␊

[22:13:52:622] <0x1b>[0;32mI (35686) TCP_IP: Written: 600<0x1b>[0m␍␊

[22:13:52:622] <0x1b>[0;32mI (35686) NimBLE: GATT procedure initiated: write; <0x1b>[0m␍␊

[22:13:52:628] <0x1b>[0;32mI (35696) NimBLE: att_handle=60 len=3␍␊

[22:13:52:634] <0x1b>[0m␍␊

[22:13:52:659] lwip_select: timeout expired␍␊

[22:13:52:659] lwip_select(60, 0x3fcd56c0, 0x0, 0x3fcd56c8, tvsec=0 tvusec=0)␍␊

[22:13:52:664] lwip_select: no timeout, returning 0␍␊

[22:13:52:669] lwip_select(60, 0x3fcd5730, 0x0, 0x3fcd5738, tvsec=1 tvusec=0)␍␊

[22:13:52:701] <0x1b>[0;32mI (35776) NimBLE: Write complete; status=0 conn_handle=2 attr_handle=60␍␊

[22:13:52:706] <0x1b>[0m␍␊

[22:13:52:706] data_sent 3000␍␍␊

[22:13:52:706] data_sent 3000␍␍␊

[22:13:52:706] <0x1b>[0;32mI (35786) NimBLE: GATT procedure initiated: write; <0x1b>[0m␍␊

[22:13:52:712] <0x1b>[0;32mI (35786) NimBLE: att_handle=60 len=3␍␊

[22:13:52:718] <0x1b>[0m␍␊

[22:13:52:801] <0x1b>[0;32mI (35876) NimBLE: Write complete; status=0 conn_handle=2 attr_handle=60␍␊

[22:13:52:806] <0x1b>[0m␍␊

[22:13:52:806] <0x1b>[0;32mI (35876) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=180␍␊

[22:13:52:811] <0x1b>[0m␍␊

[22:13:52:811] <0x1b>[0;32mI (35876) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=180␍␊

[22:13:52:823] <0x1b>[0m␍␊

[22:13:52:823] <0x1b>[0;32mI (35886) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=180␍␊

[22:13:52:828] <0x1b>[0m␍␊

[22:13:52:828] <0x1b>[0;32mI (35896) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=60␍␊

[22:13:52:839] <0x1b>[0m␍␊

[22:13:52:839] <0x1b>[0;32mI (35906) NimBLE: received notification; conn_handle=2 attr_handle=65 attr_len=1␍␊

[22:13:52:845] <0x1b>[0m␍␊

[22:13:52:845] m_data_buffer_len 600␍␍␊

[22:13:52:850] <0x1b>[0;32mI (35916) TCP_IP: Client sends data to the server...<0x1b>[0m␍␊

[22:13:52:856] lwip_send(60, data=0x3fc97168, size=600, flags=0x0)␍␊

[22:13:52:861] lwip_send(60) err=0 written=600␍␊

[22:13:52:861] <0x1b>[0;32mI (35926) TCP_IP: Written: 600<0x1b>[0m␍␊

[22:13:52:867] <0x1b>[0;32mI (35926) NimBLE: GATT procedure initiated: write; <0x1b>[0m␍␊

[22:13:52:873] <0x1b>[0;32mI (35936) NimBLE: att_handle=60 len=3␍␊

[22:13:52:877] <0x1b>[0m␍␊

[22:13:52:951] <0x1b>[0;32mI (36026) NimBLE: Write complete; status=0 conn_handle=2 attr_handle=60␍␊

[22:13:52:956] <0x1b>[0m␍␊

[22:13:52:956] data_sent 3600␍␍␊

[22:13:52:956] data_sent 3600␍␍␊

[22:13:52:956] <0x1b>[0;32mI (36036) NimBLE: GATT procedure initiated: write; <0x1b>[0m␍␊

[22:13:52:969] <0x1b>[0;32mI (36036) NimBLE: att_handle=60 len=3␍␊

[22:13:52:969] <0x1b>[0m␍␊

[22:13:53:051] <0x1b>[0;32mI (36126) NimBLE: Write complete; status=0 conn_handle=2 attr_handle=60␍␊

[22:13:53:056] <0x1b>[0m␍␊

[22:13:53:056] <0x1b>[0;32mI (36126) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=180␍␊

[22:13:53:069] <0x1b>[0m␍␊

[22:13:53:069] <0x1b>[0;32mI (36126) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=180␍␊

[22:13:53:080] <0x1b>[0m␍␊

[22:13:53:080] <0x1b>[0;32mI (36136) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=180␍␊

[22:13:53:080] <0x1b>[0m␍␊

[22:13:53:080] <0x1b>[0;32mI (36146) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=60␍␊

[22:13:53:092] <0x1b>[0m␍␊

[22:13:53:092] <0x1b>[0;32mI (36156) NimBLE: received notification; conn_handle=2 attr_handle=65 attr_len=1␍␊

[22:13:53:099] <0x1b>[0m␍␊

[22:13:53:099] m_data_buffer_len 600␍␍␊

[22:13:53:104] <0x1b>[0;32mI (36166) TCP_IP: Client sends data to the server...<0x1b>[0m␍␊

[22:13:53:107] lwip_send(60, data=0x3fc97168, size=600, flags=0x0)␍␊

[22:13:53:111] lwip_send(60) err=0 written=600␍␊

[22:13:53:111] <0x1b>[0;32mI (36176) TCP_IP: Written: 600<0x1b>[0m␍␊

[22:13:53:117] <0x1b>[0;32mI (36176) NimBLE: GATT procedure initiated: write; <0x1b>[0m␍␊

[22:13:53:123] <0x1b>[0;32mI (36186) NimBLE: att_handle=60 len=3␍␊

[22:13:53:125] <0x1b>[0m␍␊

[22:13:53:201] <0x1b>[0;32mI (36276) NimBLE: Write complete; status=0 conn_handle=2 attr_handle=60␍␊

[22:13:53:206] <0x1b>[0m␍␊

[22:13:53:206] data_sent 4200␍␍␊

[22:13:53:206] data_sent 4200␍␍␊

[22:13:53:206] <0x1b>[0;32mI (36286) NimBLE: GATT procedure initiated: write; <0x1b>[0m␍␊

[22:13:53:217] <0x1b>[0;32mI (36286) NimBLE: att_handle=60 len=3␍␊

[22:13:53:226] <0x1b>[0m␍␊

[22:13:53:301] <0x1b>[0;32mI (36376) NimBLE: Write complete; status=0 conn_handle=2 attr_handle=60␍␊

[22:13:53:306] <0x1b>[0m␍␊

[22:13:53:306] <0x1b>[0;32mI (36376) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=180␍␊

[22:13:53:317] <0x1b>[0m␍␊

[22:13:53:317] <0x1b>[0;32mI (36376) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=180␍␊

[22:13:53:328] <0x1b>[0m␍␊

[22:13:53:328] <0x1b>[0;32mI (36386) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=180␍␊

[22:13:53:328] <0x1b>[0m␍␊

[22:13:53:328] <0x1b>[0;32mI (36396) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=60␍␊

[22:13:53:340] <0x1b>[0m␍␊

[22:13:53:340] <0x1b>[0;32mI (36406) NimBLE: received notification; conn_handle=2 attr_handle=65 attr_len=1␍␊

[22:13:53:350] <0x1b>[0m␍␊

[22:13:53:350] m_data_buffer_len 600␍␍␊

[22:13:53:356] <0x1b>[0;32mI (36416) TCP_IP: Client sends data to the server...<0x1b>[0m␍␊

[22:13:53:356] lwip_send(60, data=0x3fc97168, size=600, flags=0x0)␍␊

[22:13:53:361] lwip_send(60) err=0 written=600␍␊

[22:13:53:361] <0x1b>[0;32mI (36426) TCP_IP: Written: 600<0x1b>[0m␍␊

[22:13:53:367] <0x1b>[0;32mI (36426) NimBLE: GATT procedure initiated: write; <0x1b>[0m␍␊

[22:13:53:373] <0x1b>[0;32mI (36436) NimBLE: att_handle=60 len=3␍␊

[22:13:53:376] <0x1b>[0m␍␊

[22:13:53:451] <0x1b>[0;32mI (36526) NimBLE: Write complete; status=0 conn_handle=2 attr_handle=60␍␊

[22:13:53:456] <0x1b>[0m␍␊

[22:13:53:456] data_sent 4800␍␍␊

[22:13:53:456] data_sent 4800␍␍␊

[22:13:53:456] <0x1b>[0;32mI (36536) NimBLE: GATT procedure initiated: write; <0x1b>[0m␍␊

[22:13:53:469] <0x1b>[0;32mI (36536) NimBLE: att_handle=60 len=3␍␊

[22:13:53:469] <0x1b>[0m␍␊

[22:13:53:551] <0x1b>[0;32mI (36626) NimBLE: Write complete; status=0 conn_handle=2 attr_handle=60␍␊

[22:13:53:556] <0x1b>[0m␍␊

[22:13:53:556] <0x1b>[0;32mI (36626) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=180␍␊

[22:13:53:568] <0x1b>[0m␍␊

[22:13:53:568] <0x1b>[0;32mI (36626) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=180␍␊

[22:13:53:579] <0x1b>[0m␍␊

[22:13:53:579] <0x1b>[0;32mI (36636) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=180␍␊

[22:13:53:579] <0x1b>[0m␍␊

[22:13:53:579] <0x1b>[0;32mI (36646) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=60␍␊

[22:13:53:591] <0x1b>[0m␍␊

[22:13:53:591] <0x1b>[0;32mI (36656) NimBLE: received notification; conn_handle=2 attr_handle=65 attr_len=1␍␊

[22:13:53:600] <0x1b>[0m␍␊

[22:13:53:600] m_data_buffer_len 600␍␍␊

[22:13:53:605] <0x1b>[0;32mI (36666) TCP_IP: Client sends data to the server...<0x1b>[0m␍␊

[22:13:53:609] lwip_send(60, data=0x3fc97168, size=600, flags=0x0)␍␊

[22:13:53:613] lwip_send(60) err=0 written=600␍␊

[22:13:53:613] <0x1b>[0;32mI (36676) TCP_IP: Written: 600<0x1b>[0m␍␊

[22:13:53:617] <0x1b>[0;32mI (36676) NimBLE: GATT procedure initiated: write; <0x1b>[0m␍␊

[22:13:53:623] <0x1b>[0;32mI (36686) NimBLE: att_handle=60 len=3␍␊

[22:13:53:626] <0x1b>[0m␍␊

[22:13:53:669] lwip_select: timeout expired␍␊

[22:13:53:669] lwip_select(60, 0x3fcd56c0, 0x0, 0x3fcd56c8, tvsec=0 tvusec=0)␍␊

[22:13:53:674] lwip_select: no timeout, returning 0␍␊

[22:13:53:679] lwip_select(60, 0x3fcd5730, 0x0, 0x3fcd5738, tvsec=1 tvusec=0)␍␊

[22:13:53:751] <0x1b>[0;32mI (36826) NimBLE: Write complete; status=0 conn_handle=2 attr_handle=60␍␊

[22:13:53:756] <0x1b>[0m␍␊

[22:13:53:756] data_sent 5400␍␍␊

[22:13:53:756] data_sent 5400␍␍␊

[22:13:53:756] <0x1b>[0;32mI (36836) NimBLE: GATT procedure initiated: write; <0x1b>[0m␍␊

[22:13:53:764] <0x1b>[0;32mI (36836) NimBLE: att_handle=60 len=3␍␊

[22:13:53:769] <0x1b>[0m␍␊

[22:13:53:951] <0x1b>[0;32mI (37026) NimBLE: Write complete; status=0 conn_handle=2 attr_handle=60␍␊

[22:13:53:956] <0x1b>[0m␍␊

[22:13:53:956] <0x1b>[0;32mI (37026) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=180␍␊

[22:13:53:969] <0x1b>[0m␍␊

[22:13:53:969] <0x1b>[0;32mI (37026) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=180␍␊

[22:13:53:981] <0x1b>[0m␍␊

[22:13:53:981] <0x1b>[0;32mI (37036) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=180␍␊

[22:13:53:981] <0x1b>[0m␍␊

[22:13:53:981] <0x1b>[0;32mI (37046) NimBLE: received notification; conn_handle=2 attr_handle=62 attr_len=60␍␊

[22:13:53:993] <0x1b>[0m␍␊

[22:13:53:993] <0x1b>[0;32mI (37056) NimBLE: received notification; conn_handle=2 attr_handle=65 attr_len=1␍␊

[22:13:54:002] <0x1b>[0m␍␊

[22:13:54:002] m_data_buffer_len 600␍␍␊

[22:13:54:002] <0x1b>[0;32mI (37066) TCP_IP: Client sends data to the server...<0x1b>[0m␍␊

[22:13:54:007] lwip_send(60, data=0x3fc97168, size=600, flags=0x0)␍␊

[22:13:54:011] lwip_send(60) err=0 written=344␍␊

[22:13:54:011] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:54:017] lwip_send(60) err=-7 written=0␍␊

[22:13:54:017] written -1 11␍␍␊

[22:13:54:109] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:54:109] lwip_send(60) err=-7 written=0␍␊

[22:13:54:119] written -1 11␍␍␊

[22:13:54:209] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:54:209] lwip_send(60) err=-7 written=0␍␊

[22:13:54:219] written -1 11␍␍␊

[22:13:54:309] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:54:309] lwip_send(60) err=-7 written=0␍␊

[22:13:54:319] written -1 11␍␍␊

[22:13:54:409] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:54:409] lwip_send(60) err=-7 written=0␍␊

[22:13:54:419] written -1 11␍␍␊

[22:13:54:509] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:54:509] lwip_send(60) err=-7 written=0␍␊

[22:13:54:519] written -1 11␍␍␊

[22:13:54:609] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:54:609] lwip_send(60) err=-7 written=0␍␊

[22:13:54:619] written -1 11␍␍␊

[22:13:54:678] lwip_select: timeout expired␍␊

[22:13:54:678] lwip_select(60, 0x3fcd56c0, 0x0, 0x3fcd56c8, tvsec=0 tvusec=0)␍␊

[22:13:54:688] lwip_select: no timeout, returning 0␍␊

[22:13:54:699] lwip_select(60, 0x3fcd5730, 0x0, 0x3fcd5738, tvsec=1 tvusec=0)␍␊

[22:13:54:709] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:54:709] lwip_send(60) err=-7 written=0␍␊

[22:13:54:719] written -1 11␍␍␊

[22:13:54:809] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:54:809] lwip_send(60) err=-7 written=0␍␊

[22:13:54:819] written -1 11␍␍␊

[22:13:54:909] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:54:909] lwip_send(60) err=-7 written=0␍␊

[22:13:54:919] written -1 11␍␍␊

[22:13:55:008] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:55:008] lwip_send(60) err=-7 written=0␍␊

[22:13:55:013] written -1 11␍␍␊

[22:13:55:108] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:55:108] lwip_send(60) err=-7 written=0␍␊

[22:13:55:117] written -1 11␍␍␊

[22:13:55:209] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:55:209] lwip_send(60) err=-7 written=0␍␊

[22:13:55:219] written -1 11␍␍␊

[22:13:55:309] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:55:309] lwip_send(60) err=-7 written=0␍␊

[22:13:55:319] written -1 11␍␍␊

[22:13:55:409] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:55:409] lwip_send(60) err=-7 written=0␍␊

[22:13:55:419] written -1 11␍␍␊

[22:13:55:509] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:55:509] lwip_send(60) err=-7 written=0␍␊

[22:13:55:519] written -1 11␍␍␊

[22:13:55:609] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:55:609] lwip_send(60) err=-7 written=0␍␊

[22:13:55:618] written -1 11␍␍␊

[22:13:55:689] lwip_select: timeout expired␍␊

[22:13:55:689] lwip_select(60, 0x3fcd56c0, 0x0, 0x3fcd56c8, tvsec=0 tvusec=0)␍␊

[22:13:55:699] lwip_select: no timeout, returning 0␍␊

[22:13:55:708] lwip_select(60, 0x3fcd5730, 0x0, 0x3fcd5738, tvsec=1 tvusec=0)␍␊

[22:13:55:717] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:55:717] lwip_send(60) err=-7 written=0␍␊

[22:13:55:717] written -1 11␍␍␊

[22:13:55:809] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:55:809] lwip_send(60) err=-7 written=0␍␊

[22:13:55:819] written -1 11␍␍␊

[22:13:55:909] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:55:909] lwip_send(60) err=-7 written=0␍␊

[22:13:55:919] written -1 11␍␍␊

[22:13:56:009] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:56:009] lwip_send(60) err=-7 written=0␍␊

[22:13:56:018] written -1 11␍␍␊

[22:13:56:109] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:56:109] lwip_send(60) err=-7 written=0␍␊

[22:13:56:118] written -1 11␍␍␊

[22:13:56:209] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:56:209] lwip_send(60) err=-7 written=0␍␊

[22:13:56:219] written -1 11␍␍␊

[22:13:56:309] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:56:309] lwip_send(60) err=-7 written=0␍␊

[22:13:56:319] written -1 11␍␍␊

[22:13:56:409] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:56:409] lwip_send(60) err=-7 written=0␍␊

[22:13:56:419] written -1 11␍␍␊

[22:13:56:509] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:56:509] lwip_send(60) err=-7 written=0␍␊

[22:13:56:519] written -1 11␍␍␊

[22:13:56:609] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:56:609] lwip_send(60) err=-7 written=0␍␊

[22:13:56:619] written -1 11␍␍␊

[22:13:56:698] lwip_select: timeout expired␍␊

[22:13:56:698] lwip_select(60, 0x3fcd56c0, 0x0, 0x3fcd56c8, tvsec=0 tvusec=0)␍␊

[22:13:56:708] lwip_select: no timeout, returning 0␍␊

[22:13:56:717] lwip_select(60, 0x3fcd5730, 0x0, 0x3fcd5738, tvsec=1 tvusec=0)␍␊

[22:13:56:717] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:56:717] lwip_send(60) err=-7 written=0␍␊

[22:13:56:728] written -1 11␍␍␊

[22:13:56:809] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:56:809] lwip_send(60) err=-7 written=0␍␊

[22:13:56:818] written -1 11␍␍␊

[22:13:56:909] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:56:909] lwip_send(60) err=-7 written=0␍␊

[22:13:56:919] written -1 11␍␍␊

[22:13:57:008] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:57:008] lwip_send(60) err=-7 written=0␍␊

[22:13:57:018] written -1 11␍␍␊

[22:13:57:108] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:57:108] lwip_send(60) err=-7 written=0␍␊

[22:13:57:115] written -1 11␍␍␊

[22:13:57:209] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:57:209] lwip_send(60) err=-7 written=0␍␊

[22:13:57:218] written -1 11␍␍␊

[22:13:57:309] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:57:309] lwip_send(60) err=-7 written=0␍␊

[22:13:57:321] written -1 11␍␍␊

[22:13:57:409] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:57:409] lwip_send(60) err=-7 written=0␍␊

[22:13:57:421] written -1 11␍␍␊

[22:13:57:509] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:57:509] lwip_send(60) err=-7 written=0␍␊

[22:13:57:518] written -1 11␍␍␊

[22:13:57:609] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:57:609] lwip_send(60) err=-7 written=0␍␊

[22:13:57:619] written -1 11␍␍␊

[22:13:57:709] lwip_select: timeout expired␍␊

[22:13:57:709] lwip_select(60, 0x3fcd56c0, 0x0, 0x3fcd56c8, tvsec=0 tvusec=0)␍␊

[22:13:57:719] lwip_select: no timeout, returning 0␍␊

[22:13:57:719] lwip_select(60, 0x3fcd5730, 0x0, 0x3fcd5738, tvsec=1 tvusec=0)␍␊

[22:13:57:730] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:57:730] lwip_send(60) err=-7 written=0␍␊

[22:13:57:740] written -1 11␍␍␊

[22:13:57:819] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:57:819] lwip_send(60) err=-7 written=0␍␊

[22:13:57:828] written -1 11␍␍␊

[22:13:57:919] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:57:919] lwip_send(60) err=-7 written=0␍␊

[22:13:57:929] written -1 11␍␍␊

[22:13:58:018] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:58:018] lwip_send(60) err=-7 written=0␍␊

[22:13:58:024] written -1 11␍␍␊

[22:13:58:119] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:58:119] lwip_send(60) err=-7 written=0␍␊

[22:13:58:131] written -1 11␍␍␊

[22:13:58:219] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:58:219] lwip_send(60) err=-7 written=0␍␊

[22:13:58:229] written -1 11␍␍␊

[22:13:58:319] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:58:319] lwip_send(60) err=-7 written=0␍␊

[22:13:58:329] written -1 11␍␍␊

[22:13:58:419] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:58:419] lwip_send(60) err=-7 written=0␍␊

[22:13:58:428] written -1 11␍␍␊

[22:13:58:519] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:58:519] lwip_send(60) err=-7 written=0␍␊

[22:13:58:529] written -1 11␍␍␊

[22:13:58:619] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:58:619] lwip_send(60) err=-7 written=0␍␊

[22:13:58:629] written -1 11␍␍␊

[22:13:58:718] lwip_select: timeout expired␍␊

[22:13:58:718] lwip_select(60, 0x3fcd56c0, 0x0, 0x3fcd56c8, tvsec=0 tvusec=0)␍␊

[22:13:58:732] lwip_select: no timeout, returning 0␍␊

[22:13:58:732] lwip_select(60, 0x3fcd5730, 0x0, 0x3fcd5738, tvsec=1 tvusec=0)␍␊

[22:13:58:742] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:58:742] lwip_send(60) err=-7 written=0␍␊

[22:13:58:742] written -1 11␍␍␊

[22:13:58:829] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:58:829] lwip_send(60) err=-7 written=0␍␊

[22:13:58:840] written -1 11␍␍␊

[22:13:58:929] lwip_send(60, data=0x3fc972c0, size=256, flags=0x0)␍␊

[22:13:58:929] lwip_send(60) err=-7 written=0␍␊

[22:13:58:940] written -1 11␍␍␊

[22:13:59:029] socket_send TIMEOUT 50␍␍␊

[22:13:59:029] <0x1b>[0;31mE (42106) TCP_IP: Error occurred during socket_send<0x1b>[0m␍␊

[22:13:59:043] lwip_close(60)␍␊

[22:13:59:043] STOP SENDING 1␍␍␊

[Marc-Aurele]

has someone already faced something like that ? Feel free to share any idea.

Regards,

[Reenis]

That is typically expected behaviour, but specifically for a socket that is opened in non-blocking mode. You seem to expect your socket to react like it is in blocking mode. How do you open that socket, can you post code for that?

Hi, I have a pretty similar issue. In my project based on ESP-IDF 4.3.7 running on ESP32-WROOM32I have a MQTT connection established and I want to make HTTP requests using ESP HTTP Client to the webhook. Without client messages added MQTT was working stable. Now after some time (seems to be a bit random ~5-15 minutes) MQTT handled by mbedtls has an error at lwip level, where all messages tried to be sent return error.

Code: Select all

lwip_send(54) err=-7 written=0

I get it that socket buffers may be full and this should be retried after giving a time to the tiT task (or another task that is responsible for sending data from tcpip buffers to the wifi driver) as this socket is non blocking.
Unfortunately after a few seconds later it fails to send with the same error, even lwip_select has a timeout which according to the comments in code means there is nothing to do.

Code: Select all

lwip_select(55, 0x3ffb9330, 0x0, 0x0, tvsec=0 tvusec=50000)
lwip_select: timeout expired

Due to re-connection logic in our application, after few tries we drop old connection and establish a new one and then everything works fine for some time again. It looks like TX buffer / TX mailbox is full and for unknown reason it is not consumed and forced re-connection is needed to clean up buffers.
Can you give me a hint where should I look for fix or give me a bit more details how messages from buffers are further processed and passed to wifi driver?