esp-now icon indicating copy to clipboard operation
esp-now copied to clipboard

Published 20 hours ago • verified publisher icon espressif

Enable spiram causes dhcp timeout

Open sxsx2yzyz opened this issue 2 years ago • 27 comments

Chip:[esp32-wrover-e 4MBflash] With spiram enable, calling esp_now_send() before calling esp_wifi_connect() will cause dhcp to time out on getting the ip. This is my code:

static const char *TAG = "app_main";
static void ip_event_handler(void *arg, esp_event_base_t event_base,
                             int32_t event_id, void *event_data)
{
    ESP_LOGE(TAG, "ip_event_handler %d", event_id);
    return;
}
static void wifi_event_handler(void *arg, esp_event_base_t event_base,
                               int32_t event_id, void *event_data)
{
    ESP_LOGE(TAG, "wifi_event_handler %d", event_id);
    if(event_id == WIFI_EVENT_STA_START || event_id == WIFI_EVENT_STA_DISCONNECTED){
        esp_wifi_connect();
    }
    return;
}

static void wifi_init()
{
    ESP_ERROR_CHECK(esp_netif_init());
    esp_event_loop_create_default();
    esp_netif_create_default_wifi_sta();
    esp_event_handler_register(WIFI_EVENT, ESP_EVENT_ANY_ID, &wifi_event_handler, NULL);
    esp_event_handler_register(IP_EVENT, ESP_EVENT_ANY_ID, &ip_event_handler, NULL);
    wifi_init_config_t cfg = WIFI_INIT_CONFIG_DEFAULT();
    ESP_ERROR_CHECK(esp_wifi_init(&cfg));
    ESP_ERROR_CHECK(esp_wifi_set_mode(WIFI_MODE_STA));
    ESP_ERROR_CHECK(esp_wifi_set_ps(WIFI_PS_NONE));
    ESP_ERROR_CHECK(esp_wifi_start());

    wifi_config_t config = {0};
    strncpy((char *)config.sta.ssid, "ChinaNet-2.4G-3648", strlen("ChinaNet-2.4G-3648") + 1);
    strncpy((char *)config.sta.password, "quit8269", strlen("quit8269") + 1);
    esp_wifi_set_config(WIFI_IF_STA, &config);
}

static void espnow_send_task(void *arg)
{
    esp_err_t ret  = ESP_OK;
    char *data  = "hello";
    size_t size    = strlen(data);
    espnow_frame_head_t frame_head = {
        .retransmit_count = 1,
        .broadcast        = true,
        .channel = ESPNOW_CHANNEL_CURRENT,
    };
    for (;;) {
        ret = espnow_send(ESPNOW_TYPE_DATA, ESPNOW_ADDR_BROADCAST, data, size, &frame_head, portMAX_DELAY);
        if(ret != ESP_OK){
            ESP_LOGE(TAG, "Send error : %d", ret);
        }
        vTaskDelay(1000 / portTICK_RATE_MS);
    }
}

static esp_err_t espnow_recv_handle(uint8_t *src_addr, void *data,
                      size_t size, wifi_pkt_rx_ctrl_t *rx_ctrl)
{
    static uint32_t count = 0;
    ESP_LOGI(TAG, "espnow_recv, <%d> [" MACSTR "][%d][%d][%d]: %.*s", 
            count++, MAC2STR(src_addr), rx_ctrl->channel, rx_ctrl->rssi, size, size, (char *)data);
    return ESP_OK;
}

void app_main()
{
    esp_storage_init();
    wifi_init();
    espnow_config_t espnow_config = ESPNOW_INIT_CONFIG_DEFAULT();
    espnow_init(&espnow_config);
    espnow_set_type(ESPNOW_TYPE_DATA, 1, espnow_recv_handle);
    xTaskCreate(espnow_send_task, "uart_read_task", 4 * 1024, NULL, tskIDLE_PRIORITY + 1, NULL);
}

Lwip dhcp debug is enabled and all other menuconfig options are default . This is the output of disable spiram:

I (438) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (512) wifi:wifi driver task: 3ffb9a80, prio:23, stack:6656, core=0
I (512) system_api: Base MAC address is not set
I (512) system_api: read default base MAC address from EFUSE
I (522) wifi:wifi firmware version: 63017e0
I (522) wifi:wifi certification version: v7.0
I (522) wifi:config NVS flash: enabled
I (532) wifi:config nano formating: disabled
I (532) wifi:Init data frame dynamic rx buffer num: 32
I (532) wifi:Init management frame dynamic rx buffer num: 32
I (542) wifi:Init management short buffer num: 32
I (542) wifi:Init static tx buffer num: 32
I (552) wifi:Init static rx buffer size: 1600
I (552) wifi:Init static rx buffer num: 10
I (562) wifi:Init dynamic rx buffer num: 32
I (562) wifi_init: rx ba win: 6
I (562) wifi_init: tcpip mbox: 32
I (572) wifi_init: udp mbox: 6
I (572) wifi_init: tcp mbox: 6
I (582) wifi_init: tcp tx win: 5744
I (582) wifi_init: tcp rx win: 5744
I (582) wifi_init: tcp mss: 1440
I (592) wifi_init: WiFi IRAM OP enabled
I (592) wifi_init: WiFi RX IRAM OP enabled
I (602) wifi:Set ps type: 0

I (602) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
I (692) wifi:mode : sta (bc:dd:c2:cf:f0:f4)
I (692) wifi:enable tsf
E (692) app_main: wifi_event_handler 2
I (692) ESPNOW: espnow [version: 1.0] init
I (732) wifi:new:<6,2>, old:<1,0>, ap:<255,255>, sta:<6,2>, prof:2
I (732) wifi:state: init -> auth (b0)
I (752) wifi:state: auth -> assoc (0)
I (762) wifi:state: assoc -> run (10)
I (782) wifi:connected with ChinaNet-2.4G-3648, aid = 1, channel 6, 40D, bssid = d8:32:14:db:36:49
I (782) wifi:security: WPA2-PSK, phy: bgn, rssi: -56
I (792) wifi:pm start, type: 0

dhcp_start(netif=0x3ffb741c) st1
dhcp_start(): restarting DHCP configuration
dhcp_start(): starting DHCP configuration
dhcp_discover()
dhcp_discover(): dhcp state is DISCOVER
transaction id xid(d31bb883)
dhcp_discover: making request
dhcp_discover: sendto(DISCOVER, IP_ADDR_BROADCAST, LWIP_IANA_PORT_DHCP_SERVER)
dhcp_discover: deleting()ing
dhcp_discover: SELECTING
dhcp_discover(): set request timeout 500 msecs
E (832) app_main: wifi_event_handler 4
I (832) wifi:AP's beacon interval = 102400 us, DTIM period = 3
W (842) wifi:<ba-add>idx:0 (ifx:0, d8:32:14:db:36:49), tid:0, ssn:2, winSize:64
dhcp_recv(pbuf = 0x3ffb1880) from DHCP server 192.168.5.1 port 67
pbuf->len = 300
pbuf->tot_len = 300
skipping option 28 in options
searching DHCP_OPTION_MESSAGE_TYPE
DHCP_OFFER received in DHCP_STATE_SELECTING state
dhcp_handle_offer(netif=0x3ffb741c) st1
dhcp_handle_offer(): server 0x0105a8c0
dhcp_handle_offer(): offer for 0x2d05a8c0
dhcp_select(netif=0x3ffb741c) st1
dhcp_select(): dhcp state is REQUESTING
transaction id xid(d31bb883)
dhcp_select: REQUESTING
dhcp_select(): set request timeout 2000 msecs
dhcp_recv(pbuf = 0x3ffb1880) from DHCP server 192.168.5.1 port 67
pbuf->len = 300
pbuf->tot_len = 300
skipping option 28 in options
searching DHCP_OPTION_MESSAGE_TYPE
DHCP_ACK received
dhcp_check(netif=0x3ffb741c) st
dhcp_check(): dhcp state is CHECKING
dhcp_check(): set request timeout 500 msecs
dhcp_fine_tmr(): request timeout
dhcp_timeout()
dhcp_timeout(): CHECKING, ARP request timed out
dhcp_check(netif=0x3ffb741c) st
dhcp_check(): dhcp state is CHECKING
dhcp_check(): set request timeout 500 msecs
dhcp_coarse_tmr()
dhcp_fine_tmr(): request timeout
dhcp_timeout()
dhcp_timeout(): CHECKING, ARP request timed out
dhcp_bind(netif=0x3ffb741c) st1
dhcp_bind(): t0 renewal timer 86400 secs
dhcp_bind(): set request timeout 86400000 msecs
dhcp_bind(): t1 renewal timer 43200 secs
dhcp_bind(): set request timeout 43200000 msecs
dhcp_bind(): t2 rebind timer 75600 secs
dhcp_bind(): set request timeout 75600000 msecs
dhcp_bind(): IP: 0x2d05a8c0 SN: 0x00ffffff GW: 0x0105a8c0
dhcp_bind(): dhcp state is BOUND
I (1522) esp_netif_handlers: sta ip: 192.168.5.45, mask: 255.255.255.0, gw: 192.168.5.1
E (1532) app_main: ip_event_handler 0
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()

This is the output of enable spiram:

I (1372) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (1382) spiram: Reserving pool of 32K of internal memory for DMA/internal allocations
I (1432) wifi:wifi driver task: 3ffcb63c, prio:23, stack:6656, core=0
I (1432) system_api: Base MAC address is not set
I (1432) system_api: read default base MAC address from EFUSE
I (1442) wifi:wifi firmware version: 63017e0
I (1442) wifi:wifi certification version: v7.0
I (1442) wifi:config NVS flash: enabled
I (1452) wifi:config nano formating: disabled
I (1452) wifi:Init data frame dynamic rx buffer num: 32
I (1462) wifi:Init management frame dynamic rx buffer num: 32
I (1462) wifi:Init management short buffer num: 32
I (1472) wifi:Init static tx buffer num: 32
I (1472) wifi:Init tx cache buffer num: 32
I (1472) wifi:Init static rx buffer size: 1600
I (1482) wifi:Init static rx buffer num: 10
I (1482) wifi:Init dynamic rx buffer num: 32
I (1492) wifi_init: rx ba win: 6
I (1492) wifi_init: tcpip mbox: 32
I (1492) wifi_init: udp mbox: 6
I (1502) wifi_init: tcp mbox: 6
I (1502) wifi_init: tcp tx win: 5744
I (1502) wifi_init: tcp rx win: 5744
I (1512) wifi_init: tcp mss: 1440
I (1512) wifi_init: WiFi IRAM OP enabled
I (1522) wifi_init: WiFi RX IRAM OP enabled
I (1522) wifi:Set ps type: 0

I (1532) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
I (1612) wifi:mode : sta (bc:dd:c2:cf:f0:f4)
I (1612) wifi:enable tsf
E (1612) app_main: wifi_event_handler 2
I (1622) ESPNOW: espnow [version: 1.0] init
I (1622) wifi:new:<6,2>, old:<1,0>, ap:<255,255>, sta:<6,2>, prof:2
I (1622) wifi:state: init -> auth (b0)
I (1642) wifi:state: auth -> assoc (0)
I (1662) wifi:state: assoc -> run (10)
I (1692) wifi:connected with ChinaNet-2.4G-3648, aid = 1, channel 6, 40D, bssid = d8:32:14:db:36:49
I (1692) wifi:security: WPA2-PSK, phy: bgn, rssi: -52
I (1692) wifi:pm start, type: 0

dhcp_start(netif=0x3ffbd47c) st1
dhcp_start(): restarting DHCP configuration
dhcp_start(): starting DHCP configuration
dhcp_discover()
dhcp_discover(): dhcp state is DISCOVER
transaction id xid(5a53c937)
dhcp_discover: making request
dhcp_discover: sendto(DISCOVER, IP_ADDR_BROADCAST, LWIP_IANA_PORT_DHCP_SERVER)
dhcp_discover: deleting()ing
dhcp_discover: SELECTING
dhcp_discover(): set request timeout 500 msecs
E (1732) app_main: wifi_event_handler 4
I (1732) wifi:AP's beacon interval = 102400 us, DTIM period = 3
dhcp_fine_tmr(): request timeout
dhcp_timeout()
dhcp_timeout(): restarting discovery
dhcp_discover()
dhcp_discover(): dhcp state is DISCOVER
transaction id xid(5a53c937)
dhcp_discover: making request
dhcp_discover: sendto(DISCOVER, IP_ADDR_BROADCAST, LWIP_IANA_PORT_DHCP_SERVER)
dhcp_discover: deleting()ing
dhcp_discover: SELECTING
dhcp_discover(): set request timeout 1000 msecs
I (2332) app_main: espnow_recv, <0> [94:e6:86:48:82:74][6][-48][5]: hello
dhcp_coarse_tmr()
dhcp_fine_tmr(): request timeout
dhcp_timeout()
dhcp_timeout(): restarting discovery
dhcp_discover()
dhcp_discover(): dhcp state is DISCOVER
transaction id xid(5a53c937)
dhcp_discover: making request
dhcp_discover: sendto(DISCOVER, IP_ADDR_BROADCAST, LWIP_IANA_PORT_DHCP_SERVER)
dhcp_discover: deleting()ing
dhcp_discover: SELECTING
dhcp_discover(): set request timeout 2000 msecs
dhcp_coarse_tmr()
dhcp_coarse_tmr()
W (4442) wifi:<ba-add>idx:0 (ifx:0, d8:32:14:db:36:49), tid:0, ssn:2, winSize:64
dhcp_fine_tmr(): request timeout
dhcp_timeout()
dhcp_timeout(): restarting discovery
dhcp_discover()
dhcp_discover(): dhcp state is DISCOVER
transaction id xid(5a53c937)
dhcp_discover: making request
dhcp_discover: sendto(DISCOVER, IP_ADDR_BROADCAST, LWIP_IANA_PORT_DHCP_SERVER)
dhcp_discover: deleting()ing
dhcp_discover: SELECTING
dhcp_discover(): set request timeout 4000 msecs
dhcp_coarse_tmr()
dhcp_coarse_tmr()
W (6782) wifi:<ba-add>idx:1 (ifx:0, d8:32:14:db:36:49), tid:6, ssn:0, winSize:64
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_fine_tmr(): request timeout
dhcp_timeout()
dhcp_timeout(): restarting discovery
dhcp_discover()
dhcp_discover(): dhcp state is DISCOVER
transaction id xid(5a53c937)
dhcp_discover: making request
dhcp_discover: sendto(DISCOVER, IP_ADDR_BROADCAST, LWIP_IANA_PORT_DHCP_SERVER)
dhcp_discover: deleting()ing
dhcp_discover: SELECTING
dhcp_discover(): set request timeout 8000 msecs
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
I (12332) app_main: espnow_recv, <1> [94:e6:86:48:82:74][6][-38][5]: hello
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_fine_tmr(): request timeout
dhcp_timeout()
dhcp_timeout(): restarting discovery
dhcp_discover()
dhcp_discover(): dhcp state is DISCOVER
transaction id xid(5a53c937)
dhcp_discover: making request
dhcp_discover: sendto(DISCOVER, IP_ADDR_BROADCAST, LWIP_IANA_PORT_DHCP_SERVER)
dhcp_discover: deleting()ing
dhcp_discover: SELECTING
dhcp_discover(): set request timeout 15000 msecs
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
I (22332) app_main: espnow_recv, <2> [94:e6:86:48:82:74][6][-51][5]: hello
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_fine_tmr(): request timeout
dhcp_timeout()
dhcp_timeout(): restarting discovery
dhcp_discover()
dhcp_discover(): dhcp state is DISCOVER
transaction id xid(5a53c937)
dhcp_discover: making request
dhcp_discover: sendto(DISCOVER, IP_ADDR_BROADCAST, LWIP_IANA_PORT_DHCP_SERVER)
dhcp_discover: deleting()ing
dhcp_discover: SELECTING
dhcp_discover(): set request timeout 15000 msecs
I (32342) app_main: espnow_recv, <3> [94:e6:86:48:82:74][6][-44][5]: hello
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
I (42342) app_main: espnow_recv, <4> [94:e6:86:48:82:74][6][-49][5]: hello
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_fine_tmr(): request timeout
dhcp_timeout()
dhcp_timeout(): restarting discovery
dhcp_discover()
dhcp_discover(): dhcp state is DISCOVER
transaction id xid(5a53c937)
dhcp_discover: making request
dhcp_discover: sendto(DISCOVER, IP_ADDR_BROADCAST, LWIP_IANA_PORT_DHCP_SERVER)
dhcp_discover: deleting()ing
dhcp_discover: SELECTING
dhcp_discover(): set request timeout 15000 msecs
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
I (52342) app_main: espnow_recv, <5> [94:e6:86:48:82:74][6][-47][5]: hello
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_fine_tmr(): request timeout
dhcp_timeout()
dhcp_timeout(): restarting discovery
dhcp_discover()
dhcp_discover(): dhcp state is DISCOVER
transaction id xid(5a53c937)
dhcp_discover: making request
dhcp_discover: sendto(DISCOVER, IP_ADDR_BROADCAST, LWIP_IANA_PORT_DHCP_SERVER)
dhcp_discover: deleting()ing
dhcp_discover: SELECTING
dhcp_discover(): set request timeout 15000 msecs
I (62342) app_main: espnow_recv, <6> [94:e6:86:48:82:74][6][-50][5]: hello
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
I (72342) app_main: espnow_recv, <7> [94:e6:86:48:82:74][6][-43][5]: hello
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_fine_tmr(): request timeout
dhcp_timeout()
dhcp_timeout(): restarting discovery
dhcp_discover()
dhcp_discover(): dhcp state is DISCOVER
transaction id xid(5a53c937)
dhcp_discover: making request
dhcp_discover: sendto(DISCOVER, IP_ADDR_BROADCAST, LWIP_IANA_PORT_DHCP_SERVER)
dhcp_discover: deleting()ing
dhcp_discover: SELECTING
dhcp_discover(): set request timeout 15000 msecs
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()

sxsx2yzyz avatar Aug 30 '22 05:08 sxsx2yzyz

Can you reproduce the issue with spiram enable and not calling esp_now_send()?

LJYSP avatar Aug 30 '22 07:08 LJYSP

Can you reproduce the issue with spiram enable and not calling esp_now_send()?

yes

static const char *TAG = "app_main";
static void ip_event_handler(void *arg, esp_event_base_t event_base,
                             int32_t event_id, void *event_data)
{
    ESP_LOGE(TAG, "ip_event_handler %d", event_id);
    return;
}
static void wifi_event_handler(void *arg, esp_event_base_t event_base,
                               int32_t event_id, void *event_data)
{
    ESP_LOGE(TAG, "wifi_event_handler %d", event_id);
    if(event_id == WIFI_EVENT_STA_START || event_id == WIFI_EVENT_STA_DISCONNECTED){
        esp_wifi_connect();
    }
    return;
}

static void wifi_init()
{
    ESP_ERROR_CHECK(esp_netif_init());
    esp_event_loop_create_default();
    esp_netif_create_default_wifi_sta();
    esp_event_handler_register(WIFI_EVENT, ESP_EVENT_ANY_ID, &wifi_event_handler, NULL);
    esp_event_handler_register(IP_EVENT, ESP_EVENT_ANY_ID, &ip_event_handler, NULL);
    wifi_init_config_t cfg = WIFI_INIT_CONFIG_DEFAULT();
    ESP_ERROR_CHECK(esp_wifi_init(&cfg));
    ESP_ERROR_CHECK(esp_wifi_set_mode(WIFI_MODE_STA));
    ESP_ERROR_CHECK(esp_wifi_set_ps(WIFI_PS_NONE));
    ESP_ERROR_CHECK(esp_wifi_start());

    wifi_config_t config = {0};
    strncpy((char *)config.sta.ssid, "ChinaNet-2.4G-3648", strlen("ChinaNet-2.4G-3648") + 1);
    strncpy((char *)config.sta.password, "quit8269", strlen("quit8269") + 1);
    esp_wifi_set_config(WIFI_IF_STA, &config);
}

static void espnow_send_task(void *arg)
{
    esp_err_t ret  = ESP_OK;
    char *data  = "hello";
    size_t size    = strlen(data);
    espnow_frame_head_t frame_head = {
        .retransmit_count = 1,
        .broadcast        = true,
        .channel = ESPNOW_CHANNEL_CURRENT,
    };
    for (;;) {
        // ret = espnow_send(ESPNOW_TYPE_DATA, ESPNOW_ADDR_BROADCAST, data, size, &frame_head, portMAX_DELAY);
        // if(ret != ESP_OK){
        //     ESP_LOGE(TAG, "Send error : %d", ret);
        // }
        vTaskDelay(1000 / portTICK_RATE_MS);
    }
}

static esp_err_t espnow_recv_handle(uint8_t *src_addr, void *data,
                      size_t size, wifi_pkt_rx_ctrl_t *rx_ctrl)
{
    static uint32_t count = 0;
    ESP_LOGI(TAG, "espnow_recv, <%d> [" MACSTR "][%d][%d][%d]: %.*s", 
            count++, MAC2STR(src_addr), rx_ctrl->channel, rx_ctrl->rssi, size, size, (char *)data);
    return ESP_OK;
}

void app_main()
{
    esp_storage_init();
    wifi_init();
    espnow_config_t espnow_config = ESPNOW_INIT_CONFIG_DEFAULT();
    espnow_init(&espnow_config);
    espnow_set_type(ESPNOW_TYPE_DATA, 1, espnow_recv_handle);
    xTaskCreate(espnow_send_task, "uart_read_task", 4 * 1024, NULL, tskIDLE_PRIORITY + 1, NULL);
}

optput:

I (1372) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (1382) spiram: Reserving pool of 32K of internal memory for DMA/internal allocations
I (1432) wifi:wifi driver task: 3ffcb63c, prio:23, stack:6656, core=0
I (1432) system_api: Base MAC address is not set
I (1432) system_api: read default base MAC address from EFUSE
I (1442) wifi:wifi firmware version: 63017e0
I (1442) wifi:wifi certification version: v7.0
I (1442) wifi:config NVS flash: enabled
I (1452) wifi:config nano formating: disabled
I (1452) wifi:Init data frame dynamic rx buffer num: 32
I (1462) wifi:Init management frame dynamic rx buffer num: 32
I (1462) wifi:Init management short buffer num: 32
I (1472) wifi:Init static tx buffer num: 32
I (1472) wifi:Init tx cache buffer num: 32
I (1472) wifi:Init static rx buffer size: 1600
I (1482) wifi:Init static rx buffer num: 10
I (1482) wifi:Init dynamic rx buffer num: 32
I (1492) wifi_init: rx ba win: 6
I (1492) wifi_init: tcpip mbox: 32
I (1492) wifi_init: udp mbox: 6
I (1502) wifi_init: tcp mbox: 6
I (1502) wifi_init: tcp tx win: 5744
I (1502) wifi_init: tcp rx win: 5744
I (1512) wifi_init: tcp mss: 1440
I (1512) wifi_init: WiFi IRAM OP enabled
I (1522) wifi_init: WiFi RX IRAM OP enabled
I (1522) wifi:Set ps type: 0

I (1532) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
I (1612) wifi:mode : sta (bc:dd:c2:cf:f0:f4)
I (1612) wifi:enable tsf
E (1622) app_main: wifi_event_handler 2
I (1622) ESPNOW: espnow [version: 1.0] init
I (1622) wifi:new:<6,2>, old:<1,0>, ap:<255,255>, sta:<6,2>, prof:2
I (1622) wifi:state: init -> auth (b0)
I (1652) wifi:state: auth -> assoc (0)
I (1662) wifi:state: assoc -> run (10)
I (1722) wifi:connected with ChinaNet-2.4G-3648, aid = 5, channel 6, 40D, bssid = d8:32:14:db:36:49
I (1722) wifi:security: WPA2-PSK, phy: bgn, rssi: -47
I (1732) wifi:pm start, type: 0

dhcp_start(netif=0x3ffbd47c) st1
dhcp_start(): restarting DHCP configuration
dhcp_start(): starting DHCP configuration
dhcp_discover()
dhcp_discover(): dhcp state is DISCOVER
transaction id xid(dafbce77)
dhcp_discover: making request
dhcp_discover: sendto(DISCOVER, IP_ADDR_BROADCAST, LWIP_IANA_PORT_DHCP_SERVER)
dhcp_discover: deleting()ing
dhcp_discover: SELECTING
W (1762) wifi:dhcp_discover(): set request timeout 500 msecs
<ba-add>idx:0 (ifx:0, d8:32:14:db:36:49), tid:0, ssn:2, winSize:64
dhcp_recv(pbuf = 0x3ffb2920) from DHCP server 192.168.5.1 port 67
pbuf->len = 300
pbuf->tot_len = 300
I (1772) wifi:skipping option 28 in options
AP's beacon interval = 102400 us, DTIM period = 3
searching DHCP_OPTION_MESSAGE_TYPE
E (1772) app_main: wifi_event_handler 4
DHCP_OFFER received in DHCP_STATE_SELECTING state
dhcp_handle_offer(netif=0x3ffbd47c) st1
dhcp_handle_offer(): server 0x0105a8c0
dhcp_handle_offer(): offer for 0x2d05a8c0
dhcp_select(netif=0x3ffbd47c) st1
dhcp_select(): dhcp state is REQUESTING
transaction id xid(dafbce77)
dhcp_select: REQUESTING
dhcp_select(): set request timeout 2000 msecs
dhcp_recv(pbuf = 0x3ffb2920) from DHCP server 192.168.5.1 port 67
pbuf->len = 300
pbuf->tot_len = 300
skipping option 28 in options
searching DHCP_OPTION_MESSAGE_TYPE
DHCP_ACK received
dhcp_check(netif=0x3ffbd47c) st
dhcp_check(): dhcp state is CHECKING
dhcp_check(): set request timeout 500 msecs
dhcp_fine_tmr(): request timeout
dhcp_timeout()
dhcp_timeout(): CHECKING, ARP request timed out
dhcp_check(netif=0x3ffbd47c) st
dhcp_check(): dhcp state is CHECKING
dhcp_check(): set request timeout 500 msecs
dhcp_coarse_tmr()
dhcp_fine_tmr(): request timeout
dhcp_timeout()
dhcp_timeout(): CHECKING, ARP request timed out
dhcp_bind(netif=0x3ffbd47c) st1
dhcp_bind(): t0 renewal timer 86400 secs
dhcp_bind(): set request timeout 86400000 msecs
dhcp_bind(): t1 renewal timer 43200 secs
dhcp_bind(): set request timeout 43200000 msecs
dhcp_bind(): t2 rebind timer 75600 secs
dhcp_bind(): set request timeout 75600000 msecs
dhcp_bind(): IP: 0x2d05a8c0 SN: 0x00ffffff GW: 0x0105a8c0
dhcp_bind(): dhcp state is BOUND
I (2452) esp_netif_handlers: sta ip: 192.168.5.45, mask: 255.255.255.0, gw: 192.168.5.1
E (2462) app_main: ip_event_handler 0
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()
dhcp_coarse_tmr()

Successfully obtained the ip when not calling esp_now_send()

sxsx2yzyz avatar Aug 30 '22 12:08 sxsx2yzyz

Thanks for your feedback, we will analyse the issue later.

LJYSP avatar Sep 01 '22 07:09 LJYSP

Thanks for your feedback, we will analyse the issue later.

Hi,has there been any progress?

sxsx2yzyz avatar Sep 05 '22 05:09 sxsx2yzyz

DHCP is success when I use Chip:[esp32-wrover-e 2MBflash] and enable spiram with your code. ESP-IDF version is v4.4.1. SPIRAM setting: menuconfig -> component config -> ESP32-specific -> Support for external, SPI-connected RAM.

Do you have other setting about spiram? Or change another router to test?

This is my log:

I (27) boot: ESP-IDF v4.4.1-dirty 2nd stage bootloader
I (27) boot: compile time 14:26:59
I (27) boot: chip revision: 3
I (31) boot_comm: chip revision: 3, min. bootloader chip revision: 0
I (38) boot.esp32: SPI Speed      : 40MHz
I (42) boot.esp32: SPI Mode       : DIO
I (47) boot.esp32: SPI Flash Size : 2MB
I (51) boot: Enabling RNG early entropy source...
I (57) boot: Partition Table:
I (60) boot: ## Label            Usage          Type ST Offset   Length
I (68) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (75) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (83) boot:  2 factory          factory app      00 00 00010000 00100000
I (90) boot: End of partition table
I (94) boot_comm: chip revision: 3, min. application chip revision: 0
I (101) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=188f4h (100596) map
I (146) esp_image: segment 1: paddr=0002891c vaddr=3ffb0000 size=0389ch ( 14492) load
I (152) esp_image: segment 2: paddr=0002c1c0 vaddr=40080000 size=03e58h ( 15960) load
I (159) esp_image: segment 3: paddr=00030020 vaddr=400d0020 size=7a080h (499840) map
I (342) esp_image: segment 4: paddr=000aa0a8 vaddr=40083e58 size=14598h ( 83352) load
I (376) esp_image: segment 5: paddr=000be648 vaddr=50000000 size=00010h (    16) load
I (388) boot: Loaded app from partition at offset 0x10000
I (388) boot: Disabling RNG early entropy source...
I (400) psram: This chip is ESP32-D0WD
I (402) spiram: Found 64MBit SPI RAM device
I (402) spiram: SPI RAM mode: flash 40m sram 40m
I (405) spiram: PSRAM initialized, cache is in low/high (2-core) mode.
I (412) cpu_start: Pro cpu up.
I (416) cpu_start: Starting app cpu, entry point is 0x400813ec
0x400813ec: call_start_cpu1 at /home/lijingyi/esp/1-idf/hub/esp-idf-v4.4.1/components/esp_system/port/cpu_start.c:160

I (0) cpu_start: App cpu up.
I (1310) spiram: SPI SRAM memory test OK
I (1318) cpu_start: Pro cpu start user code
I (1318) cpu_start: cpu freq: 160000000
I (1318) cpu_start: Application information:
I (1321) cpu_start: Project name:     get-started
I (1327) cpu_start: App version:      v1.0-36-gbd43391-dirty
I (1333) cpu_start: Compile time:     Sep  5 2022 14:26:47
I (1339) cpu_start: ELF file SHA256:  dd0a3e1d12c24aff...
I (1345) cpu_start: ESP-IDF:          v4.4.1-dirty
I (1351) heap_init: Initializing. RAM available for dynamic allocation:
I (1358) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (1364) heap_init: At 3FFB76E8 len 00028918 (162 KiB): DRAM
I (1370) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1377) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (1383) heap_init: At 400983F0 len 00007C10 (31 KiB): IRAM
I (1390) spiram: Adding pool of 4095K of external SPI memory to heap allocator
I (1399) spi_flash: detected chip: generic
I (1402) spi_flash: flash io: dio
W (1406) spi_flash: Detected size(8192k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (1421) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (1430) spiram: Reserving pool of 32K of internal memory for DMA/internal allocations
I (1490) wifi:wifi driver task: 3ffc8784, prio:23, stack:6656, core=0
I (1490) system_api: Base MAC address is not set
I (1490) system_api: read default base MAC address from EFUSE
I (1510) wifi:wifi firmware version: 63017e0
I (1510) wifi:wifi certification version: v7.0
I (1510) wifi:config NVS flash: enabled
I (1510) wifi:config nano formating: disabled
I (1510) wifi:Init data frame dynamic rx buffer num: 32
I (1520) wifi:Init management frame dynamic rx buffer num: 32
I (1520) wifi:Init management short buffer num: 32
I (1530) wifi:Init static tx buffer num: 16
I (1530) wifi:Init tx cache buffer num: 32
I (1540) wifi:Init static rx buffer size: 1600
I (1540) wifi:Init static rx buffer num: 10
I (1540) wifi:Init dynamic rx buffer num: 32
I (1550) wifi_init: rx ba win: 6
I (1550) wifi_init: tcpip mbox: 32
I (1560) wifi_init: udp mbox: 6
I (1560) wifi_init: tcp mbox: 6
I (1560) wifi_init: tcp tx win: 5744
I (1570) wifi_init: tcp rx win: 5744
I (1570) wifi_init: tcp mss: 1440
I (1580) wifi_init: WiFi IRAM OP enabled
I (1580) wifi_init: WiFi RX IRAM OP enabled
I (1590) wifi:Set ps type: 0

I (1590) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
I (1700) wifi:mode : sta (c4:dd:57:7e:16:00)
I (1700) wifi:enable tsf
E (1710) app_main: wifi_event_handler 2
I (1710) ESPNOW: espnow [version: 1.0] init
I (1720) wifi:new:<1,1>, old:<1,0>, ap:<255,255>, sta:<1,1>, prof:1
I (1730) wifi:state: init -> auth (b0)
I (1730) wifi:state: auth -> assoc (0)
I (1740) wifi:state: assoc -> run (10)
I (1740) wifi:connected with ljyssid, aid = 3, channel 1, 40U, bssid = 70:af:6a:02:3c:22
I (1740) wifi:security: Open Auth, phy: bgn, rssi: -24
I (1750) wifi:pm start, type: 0

E (1750) app_main: wifi_event_handler 4
W (1760) wifi:<ba-add>idx:0 (ifx:0, 70:af:6a:02:3c:22), tid:0, ssn:0, winSize:64
I (1830) wifi:AP's beacon interval = 102400 us, DTIM period = 1
I (1900) app_main: espnow_recv, <0> [24:0a:c4:d6:d3:00][1][-35][5]: hello
I (2900) app_main: espnow_recv, <1> [24:0a:c4:d6:d3:00][1][-35][5]: hello
I (2980) esp_netif_handlers: sta ip: 192.168.0.32, mask: 255.255.255.0, gw: 192.168.0.1
E (2980) app_main: ip_event_handler 0
I (3900) app_main: espnow_recv, <2> [24:0a:c4:d6:d3:00][1][-36][5]: hello
I (4900) app_main: espnow_recv, <3> [24:0a:c4:d6:d3:00][1][-50][5]: hello

LJYSP avatar Sep 05 '22 07:09 LJYSP

when the router is set open security, dhcp is OK. when the router is set security, we reproduce the connection is not success. We will work on the issue and feedback later.

LJYSP avatar Sep 05 '22 07:09 LJYSP

when the router is set open security, dhcp is OK. when the router is set security, we reproduce the connection is not success. We will work on the issue and feedback later.

Ok,thank you

sxsx2yzyz avatar Sep 05 '22 08:09 sxsx2yzyz

What's your Router Model ? It seems the issue is related to router model, I test anothor router and connection & dhcp is ok

LJYSP avatar Sep 05 '22 08:09 LJYSP

Tenda AC1200 2.4G+5G

sxsx2yzyz avatar Sep 05 '22 09:09 sxsx2yzyz

901662369368_ pic The router's LAN ip is 192.168.5.1

sxsx2yzyz avatar Sep 05 '22 09:09 sxsx2yzyz

I just tried using mobile hotspot and found that no matter what the security setting is, connect and dhcp is ok.

sxsx2yzyz avatar Sep 05 '22 09:09 sxsx2yzyz

@sxsx2yzyz Is your router Tenda AC11? I see AC7/AC10/AC11 all support AC1200

zhangyanjiaoesp avatar Sep 06 '22 11:09 zhangyanjiaoesp

911662513203_ pic @zhangyanjiaoesp I'm not sure, but it only has ac1200 marked on it

sxsx2yzyz avatar Sep 07 '22 01:09 sxsx2yzyz

ok, I will try to use the same router to reproduce this issue. By the way, can you provide any sniffer packets?

zhangyanjiaoesp avatar Sep 07 '22 02:09 zhangyanjiaoesp

@zhangyanjiaoesp Sorry,i don't know what sniffer packets are

sxsx2yzyz avatar Sep 07 '22 06:09 sxsx2yzyz

@zhangyanjiaoesp How do I get it？

sxsx2yzyz avatar Sep 07 '22 06:09 sxsx2yzyz

you can use Ominipeek or Wireshark to capture the wifi packets.

zhangyanjiaoesp avatar Sep 07 '22 06:09 zhangyanjiaoesp

@zhangyanjiaoesp What information do I need to pay attention to?

sxsx2yzyz avatar Sep 07 '22 07:09 sxsx2yzyz

Can you reproduce the problem if the AP set to open ? If yes, you can just capture the packets from test beginning. If not, you need to set the Wireshark as this , and then start capture the packets from the test beginning.

zhangyanjiaoesp avatar Sep 07 '22 07:09 zhangyanjiaoesp

I have reproduced your issue using a new Tenda router, will find the root cause ASAP.

zhangyanjiaoesp avatar Sep 19 '22 08:09 zhangyanjiaoesp

I have reproduced your issue using a new Tenda router, will find the root cause ASAP.

OK thanks

sxsx2yzyz avatar Sep 20 '22 02:09 sxsx2yzyz

I have reproduced your issue using a new Tenda router, will find the root cause ASAP.

Hi,has there been any progress?

sxsx2yzyz avatar Sep 28 '22 01:09 sxsx2yzyz

Sorry there are other things blocked this issue, we will raise the priority to deal with this issue

zhangyanjiaoesp avatar Sep 28 '22 10:09 zhangyanjiaoesp

Sorry there are other things blocked this issue, we will raise the priority to deal with this issue

OK

sxsx2yzyz avatar Sep 29 '22 03:09 sxsx2yzyz

@sxsx2yzyz We have found the root cause, and will merge the bug fix ASAP. The fix will be backported to v4.4 also.

zhangyanjiaoesp avatar Sep 29 '22 08:09 zhangyanjiaoesp

COOL!!! thank you

sxsx2yzyz avatar Sep 29 '22 10:09 sxsx2yzyz

@sxsx2yzyz This fix has been merged into master branch 3b7d9faf78053ffc9ef0a6f518caac4050c18610, backport for v4.4 still need time.

zhangyanjiaoesp avatar Oct 12 '22 06:10 zhangyanjiaoesp

@sxsx2yzyz This fix has been merged into release/v4.4， please use the release/v4.4 instead of IDF v4.4.1. Checkout the branch by: git clone -b release/v4.4 --recursive https://github.com/espressif/esp-idf.git

Or wait for the next release version v4.4.x including the fix.

LJYSP avatar Oct 19 '22 11:10 LJYSP

@sxsx2yzyz This fix has been merged into release/v4.4， please use the release/v4.4 instead of IDF v4.4.1. Checkout the branch by: git clone -b release/v4.4 --recursive https://gitlab.espressif.cn:6688/espressif/esp-idf.git

Or wait for the next release version v4.4.x including the fix.

ok thank you

sxsx2yzyz avatar Oct 20 '22 12:10 sxsx2yzyz