Periodic ping problem (IDFGH-3203)

[mohamed-elsabagh]

I am using latest esp-idf on master branch, and in my application I ported the ping example and I am trying to call it every 30 seconds, to test connectivity of my device.

#include "ping_driver.h"
#include "AppConfig.h"
#include <stdio.h>
#include <string.h>
#include "esp_log.h"
#include "lwip/inet.h"
#include "lwip/netdb.h"
#include "lwip/sockets.h"
#include "ping/ping_sock.h"

#define TAG  "PING_DRIVER"

/* External Variables */
internet_state current_internet_state = { 0 };

/* Private functions */
static void cmd_ping_on_ping_success(esp_ping_handle_t hdl, void *args);
static void cmd_ping_on_ping_timeout(esp_ping_handle_t hdl, void *args);
static void cmd_ping_on_ping_end(esp_ping_handle_t hdl, void *args);


uint16_t do_ping_cmd(uint32_t timeout_ms, uint32_t interval_ms, uint32_t data_size,
                     uint32_t count, uint32_t tos, const uint8_t *host)
{
    esp_ping_config_t config = ESP_PING_DEFAULT_CONFIG();

    config.timeout_ms = (uint32_t)(timeout_ms);
    config.interval_ms = (uint32_t)(interval_ms);
    config.data_size = (uint32_t)(data_size);
    config.count = (uint32_t)(count);
    config.tos = (uint32_t)(tos);

    // parse IP address
    ip_addr_t target_addr;
    struct addrinfo hint;
    struct addrinfo *res = NULL;
    memset(&hint, 0, sizeof(hint));
    memset(&target_addr, 0, sizeof(target_addr));
    /* convert domain name to IP address */
    if (getaddrinfo((const char *)host, NULL, &hint, &res) != 0)
    {
        ESP_LOGE(TAG, "ping: unknown host %s", host);
        return 1;
    }

    ESP_LOGI(TAG, "host: %s", host);
    if (res->ai_family == AF_INET)
    {
        struct in_addr addr4 = ((struct sockaddr_in *)(res->ai_addr))->sin_addr;
        inet_addr_to_ip4addr(ip_2_ip4(&target_addr), &addr4);
    }
    else
    {
        struct in6_addr addr6 = ((struct sockaddr_in6 *)(res->ai_addr))->sin6_addr;
        inet6_addr_to_ip6addr(ip_2_ip6(&target_addr), &addr6);
    }
    freeaddrinfo(res);
    config.target_addr = target_addr;

    /* set callback functions */
    esp_ping_callbacks_t cbs = {
        .on_ping_success = cmd_ping_on_ping_success,
        .on_ping_timeout = cmd_ping_on_ping_timeout,
        .on_ping_end = cmd_ping_on_ping_end,
        .cb_args = NULL
    };
    esp_ping_handle_t ping;
    esp_ping_new_session(&config, &cbs, &ping);
    esp_ping_start(ping);

    return 0;
}

void cmd_ping_on_ping_success(esp_ping_handle_t hdl, void *args)
{
    uint8_t ttl;
    uint16_t seqno;
    uint32_t elapsed_time, recv_len;
    ip_addr_t target_addr;

    esp_ping_get_profile(hdl, ESP_PING_PROF_SEQNO, &seqno, sizeof(seqno));
    esp_ping_get_profile(hdl, ESP_PING_PROF_TTL, &ttl, sizeof(ttl));
    esp_ping_get_profile(hdl, ESP_PING_PROF_IPADDR, &target_addr, sizeof(target_addr));
    esp_ping_get_profile(hdl, ESP_PING_PROF_SIZE, &recv_len, sizeof(recv_len));
    esp_ping_get_profile(hdl, ESP_PING_PROF_TIMEGAP, &elapsed_time, sizeof(elapsed_time));
    ESP_LOGI(TAG, "%d bytes from %s icmp_seq=%d ttl=%d time=%d ms",
             recv_len, inet_ntoa(target_addr.u_addr.ip4), seqno, ttl, elapsed_time);
}

void cmd_ping_on_ping_timeout(esp_ping_handle_t hdl, void *args)
{
    uint16_t seqno;
    ip_addr_t target_addr;

    esp_ping_get_profile(hdl, ESP_PING_PROF_SEQNO, &seqno, sizeof(seqno));
    esp_ping_get_profile(hdl, ESP_PING_PROF_IPADDR, &target_addr, sizeof(target_addr));
    ESP_LOGI(TAG, "From %s icmp_seq=%d timeout",
             inet_ntoa(target_addr.u_addr.ip4), seqno);
}

void cmd_ping_on_ping_end(esp_ping_handle_t hdl, void *args)
{
    ip_addr_t target_addr;
    uint32_t transmitted;
    uint32_t received;
    uint32_t total_time_ms;

    esp_ping_get_profile(hdl, ESP_PING_PROF_REQUEST, &transmitted, sizeof(transmitted));
    esp_ping_get_profile(hdl, ESP_PING_PROF_REPLY, &received, sizeof(received));
    esp_ping_get_profile(hdl, ESP_PING_PROF_IPADDR, &target_addr, sizeof(target_addr));
    esp_ping_get_profile(hdl, ESP_PING_PROF_DURATION, &total_time_ms, sizeof(total_time_ms));
    uint32_t loss = (uint32_t)((1 - ((float)received) / transmitted) * 100);
    if (IP_IS_V4(&target_addr))
    {
        ESP_LOGI(TAG, "\n--- %s ping statistics ---\n",
                 inet_ntoa(*ip_2_ip4(&target_addr)));
    }
    else
    {
        ESP_LOGI(TAG, "\n--- %s ping statistics ---\n",
                 inet6_ntoa(*ip_2_ip6(&target_addr)));
    }
    ESP_LOGI(TAG, "%d packets transmitted, %d received, %d%% packet loss, time %dms",
             transmitted, received, loss, total_time_ms);
    // delete the ping sessions, so that we clean up all resources and can create a new ping session
    // we don't have to call delete function in the callback, instead we can call delete function from other tasks
    esp_ping_delete_session(hdl);

    if (transmitted == received)
    {
        current_internet_state.state = INTERNET_STATE_CONNECTED;
    }
    else
    {
        current_internet_state.state = INTERNET_STATE_DISCONNECTED;
    }
}

here is the source code I am running and I am calling this FreeRTOS task

void vPingTask(void *arg)
{
    for (;;)
    {
        ESP_LOGI(TAG, "Ping Loop Called");
        // Wait for ping loop
        vTaskDelay(PING_LOOP_TIMER / portTICK_PERIOD_MS);
        do_ping_cmd(PING_TIMEOUT_MS, PING_INTERVAL_MS, PING_DATA_SIZE,
                    PING_COUNT, PING_TYPE_OF_SERVICE, PING_HOST);
    }
}

The functions is working very good for like 20 or 30 minutes and then I find that I get this error

abort() was called at PC 0x40083f20 on core 1
0x40083f20: lock_acquire_generic at E:/ESP/esp-idf/components/newlib/locks.c:142


Backtrace:0x4008e211:0x3ffc7e10 0x4008e221:0x3ffc7e30 0x4009691d:0x3ffc7e50 0x40083f20:0x3ffc7ec0 0x40084035:0x3ffc7f00 0x401baa69:0x3ffc7f20 0x401b1bad:0x3ffc81e0 0x401b1b35:0x3ffc8230 0x400914c7:0x3ffc8260 0x4009214f:0x3ffc8290 0x401538fc:0x3ffc82d0 0x40141cef:0x3ffc82f0 0x40154642:0x3ffc8320 0x4013f6fa:0x3ffc8360 0x400d7343:0x3ffc83b0 0x400d7411:0x3ffc8460
0x4008e211: panic_abort at E:/ESP/esp-idf/components/esp_system/panic.c:341

0x4008e221: esp_system_abort at E:/ESP/esp-idf/components/esp_system/system_api.c:68

0x4009691d: abort at E:/ESP/esp-idf/components/newlib/abort.c:46

0x40083f20: lock_acquire_generic at E:/ESP/esp-idf/components/newlib/locks.c:142

0x40084035: _lock_acquire_recursive at E:/ESP/esp-idf/components/newlib/locks.c:170

0x401baa69: _vfiprintf_r at /builds/idf/crosstool-NG/.build/HOST-i686-w64-mingw32/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/vfprintf.c:853 (discriminator 2)

0x401b1bad: fiprintf at /builds/idf/crosstool-NG/.build/HOST-i686-w64-mingw32/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/fiprintf.c:48

0x401b1b35: __assert_func at /builds/idf/crosstool-NG/.build/HOST-i686-w64-mingw32/xtensa-esp32-elf/src/newlib/newlib/libc/stdlib/assert.c:58 (discriminator 8)

0x400914c7: spinlock_acquire at E:/ESP/esp-idf/components/soc/include/soc/spinlock.h:110
 (inlined by) vPortCPUAcquireMutex at E:/ESP/esp-idf/components/freertos/xtensa/include/freertos/portmacro.h:202
 (inlined by) vPortEnterCritical at E:/ESP/esp-idf/components/freertos/xtensa/port.c:394

0x4009214f: xQueueGenericReceive at E:/ESP/esp-idf/components/freertos/queue.c:1461 (discriminator 4)

0x401538fc: sys_arch_sem_wait at E:/ESP/esp-idf/components/lwip/port/esp32/freertos/sys_arch.c:180

0x40141cef: tcpip_send_msg_wait_sem at E:/ESP/esp-idf/components/lwip/lwip/src/api/tcpip.c:462

0x40154642: netconn_gethostbyname_addrtype at E:/ESP/esp-idf/components/lwip/lwip/src/api/api_lib.c:1338 (discriminator 2)

0x4013f6fa: lwip_getaddrinfo at E:/ESP/esp-idf/components/lwip/lwip/src/api/netdb.c:342

0x400d7343: do_ping_cmd at e:\projects\esp32\build/../components/connection/ping_driver.c:40

0x400d7411: vPingTask at e:\projects\esp32\build/../components/connection/ping_application.c:26

and this refers to line if (getaddrinfo((const char *)host, NULL, &hint, &res) != 0)

[freakyxue]

hi @mohamed-elsabagh
Can you provide a detailed demo for me to reproduce this problem?

[mohamed-elsabagh]

This is more or less the whole project, application layer and driver layer

[freakyxue]

hi @mohamed-elsabagh

I'm using your code to reproduce the problem

[AxelLin]

@mohamed-elsabagh
Check if the patch in this thread helps:
#5762

[ESP-Marius]

I think this error is unrelated to #5762. That one was introduced during the time.c refactoring, while this problem seems to be from before that time.

The spinlocks here are called from a freertos critical section and shouldn't have the same issues.

The assert which triggers this seems to be spinlock.h:110, which makes me think this isn't the latest idf-master code. Looks like this might be an older version from before 4198485 was merged. I'd suggest OP update IDF if possible and see if that fixes the issue.

[freakyxue]

hi @mohamed-elsabagh
I used your code to hang up for 12 hours, no recurrence problem.
You can upgrade to the latest master to see if the problem can recur

[mohamed-elsabagh]

ok I will update to latest master branch and see if this fix the problem thanks so much

[Alvin1Zhang]

@mohamed-elsabagh Thanks for reporting, would you please help share if any updates for this issue? Thanks.

[Alvin1Zhang]

@mohamed-elsabagh Thanks for reporting, would you please help share if any updates for this issue? Thanks.

[mohamed-elsabagh]

I am still experiencing this issue every once and while, but it is less frequent so I decided to move over

[xueyunfei998]

hi @mohamed-elsabagh

Does this problem recur in the latest master？
Please give me feedback on the test.

[Alvin1Zhang]

Thanks for reporting and sorry for slow turnaround, feel free to reopen if the issue happens again.