Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

MODBUS TCP slave crash on start after stop (IDFGH-6568) #8211

Closed
oachkatzalschwoaf opened this issue Jan 8, 2022 · 13 comments
Closed

MODBUS TCP slave crash on start after stop (IDFGH-6568) #8211

oachkatzalschwoaf opened this issue Jan 8, 2022 · 13 comments
Labels
Resolution: Done Issue is done internally Status: Done Issue is done internally

Comments

@oachkatzalschwoaf
Copy link

Environment

  • Development Kit: ESP32 NodeMCU + custom ESP32-S2 board
  • Module or chip used: ESP32-WROOM-32
  • IDF version: v4.3.2
  • Operating System: Windows
  • Using an IDE: Visual Studio Code - Espressif IDF

Problem Description

Crash/Guru Mediation when trying to initialize modbus-tcp after it got stopped.
Discovered on custom ESP32-S2, reproduced with example code on ESP32

Steps to reproduce

initialize modbus tcp as described in documentation: https://docs.espressif.com/projects/esp-idf/en/latest/esp32/api-reference/protocols/modbus.html?highlight=modbus#modbus-slave-api-overview

  1. start/connect to wifi

  2. mbc_slave_init_tcp()

  3. mbc_slave_setup()

  4. mbc_slave_set_descriptor()

  5. mbc_slave_start()

    • modbus-tcp is running
  6. mbc_slave_destroy()

  7. goto steps 2-5

    • Guru Meditation Error: Core 0 panic'ed (StoreProhibited). Exception was unhandled.

Code to reproduce this issue

Based on example mb_tcp_slave - changes:
Configured CONFIG_EXAMPLE_WIFI_SSID and CONFIG_EXAMPLE_WIFI_PASSWORD

modified app_main:

void app_main(void)
{
    ESP_ERROR_CHECK(init_services());

    // Set UART log level
    esp_log_level_set(SLAVE_TAG, ESP_LOG_INFO);

    mb_communication_info_t comm_info = { 0 };

    comm_info.ip_addr_type = MB_IPV4;
    comm_info.ip_mode = MB_MODE_TCP;

    comm_info.ip_port = MB_TCP_PORT_NUMBER;
    ESP_ERROR_CHECK(slave_init(&comm_info));

    // The Modbus slave logic is located in this function (user handling of Modbus)
    // slave_operation_func(NULL);

    while(1){
        vTaskDelay(2000);
        ESP_LOGW(SLAVE_TAG, "Close Modbus...");
        slave_destroy();
        vTaskDelay(2000);
        ESP_LOGW(SLAVE_TAG, "Start Modbus...");
        slave_init(&comm_info);					// < CRASH!!!!
    }


    ESP_ERROR_CHECK(slave_destroy());
    ESP_ERROR_CHECK(destroy_services());
}

Debug Logs

...
I (6938) example_connect: - IPv4 address: 192.168.1.22
I (6948) wifi:Set ps type: 0

D (6948) MB_PORT_COMMON: vMBPortSetMode: Port enter critical.
D (6958) MB_PORT_COMMON: vMBPortSetMode: Port exit critical
I (6968) MB_TCP_SLAVE_PORT: Protocol stack initialized.
I (6968) MB_TCP_SLAVE_PORT: Socket (#54), listener  on port: 502, errno=0
W (27028) SLAVE_TEST: Close Modbus...
D (27028) MB_PORT_COMMON: vMBPortSetMode: Port enter critical.
D (27028) MB_PORT_COMMON: vMBPortSetMode: Port exit critical
W (47028) SLAVE_TEST: Start Modbus...
D (47028) MB_PORT_COMMON: vMBPortSetMode: Port enter critical.
D (47028) MB_PORT_COMMON: vMBPortSetMode: Port exit critical
Guru Meditation Error: Core  0 panic'ed (StoreProhibited). Exception was unhandled.

Core  0 register dump:
PC      : 0x4008d8ee  PS      : 0x00060f33  A0      : 0x8008e39a  A1      : 0x3ffbad90
A2      : 0x3ffb828c  A3      : 0x00000024  A4      : 0x00060b20  A5      : 0x00060923
A6      : 0x00000001  A7      : 0x00000001  A8      : 0x3ffc6f88  A9      : 0x00000019
A10     : 0x3ffb828c  A11     : 0x00000000  A12     : 0x00000003  A13     : 0x00060f23
A14     : 0x00000001  A15     : 0x00000001  SAR     : 0x00000017  EXCCAUSE: 0x0000001d
EXCVADDR: 0x0000000f  LBEG    : 0x400014fd  LEND    : 0x4000150d  LCOUNT  : 0xfffffffd

Backtrace:0x4008d8eb:0x3ffbad90 0x4008e397:0x3ffbadb0 0x400817e5:0x3ffbadd0 0x40081819:0x3ffbadf0 0x4008fb41:0x3ffbae10 0x4008ba9e:0x3ffbae30 0x400d7523:0x3ffbae50 0x400d73ba:0x3ffbae80 0x400d669f:0x3ffbaeb0 0x400d6919:0x3ffbaf00 0x401438d5:0x3ffbaf40 0x4008c239:0x3ffbaf60

@espressif-bot espressif-bot added the Status: Opened Issue is new label Jan 8, 2022
@github-actions github-actions bot changed the title MODBUS TCP slave crash on start after stop MODBUS TCP slave crash on start after stop (IDFGH-6568) Jan 8, 2022
@alisitsyn
Copy link
Collaborator

alisitsyn commented Jan 10, 2022

Hi @oachkatzalschwoaf ,

Thank you for reporting this issue. The issue is supposed to be fixed in the commits:
5a0b570 (master)
6c1c6a3 (slave)
61f3af0 (tcp_slave) - have not been backported
5944433 (tcp_master tcp_slave)

I will check this ASAP. Could you check these commits on your side? Thanks.

@alisitsyn
Copy link
Collaborator

@oachkatzalschwoaf ,

The issue is confirmed. Please do the following to fix the issue:

  1. The components/freemodbus/tcp_slave/modbus_controller/mbc_tcp_slave.c::mbc_tcp_slave_destroy() function is missing the initialization of mbs_interface_ptr=NULL.
    The patch to apply: git apply 0001_fix_tcp_slave_destroy.patch.log
  2. Please use the command git cherry-pick 61f3af0 which applies the fixes to correctly cleanup lwip internals.

The log after the fix is below:
tcp_slave_fix_destroy.log

Please try the above and let me know the result. Thanks.

@oachkatzalschwoaf
Copy link
Author

@alisitsyn

now its working but somewehere might be a memory leak
each init/destroy-cycle 16-36bytes are lost:

tcp_slave_memory_leak.log

    while(1){
        vTaskDelay(1000/portTICK_PERIOD_MS);
        ESP_LOGW(SLAVE_TAG, "Close Modbus...");
        slave_destroy();
        ESP_LOGI("RTOS", "    total_free_bytes:      destroyed: %d", heap_caps_get_free_size(MALLOC_CAP_INTERNAL));
        vTaskDelay(100/portTICK_PERIOD_MS);
        ESP_LOGW(SLAVE_TAG, "Start Modbus...");
        slave_init(&comm_info);
        ESP_LOGI("RTOS", "    total_free_bytes:     init:  %d", heap_caps_get_free_size(MALLOC_CAP_INTERNAL));
    }

@alisitsyn
Copy link
Collaborator

alisitsyn commented Jan 11, 2022

Hi @oachkatzalschwoaf,

I think what you are measuring here is the cost of heap fragmentation.
I checked again the Modbus stack allocations. My check shows that all allocated blocks for structures/buffers are freed at destroying.
The Modbus stack uses WIFI and the LWIP and intensively allocates and frees memory when starts and destroys stack. The heap allocator has the metadata headers for each allocated block = 4 bytes. The more fragmentation, the more total free heap size is also lost due to lots of non-contiguous free blocks that each needs their own 4-byte header.

UPDATE:
The components /freemodbus/tcp_slave/port/port_tcp_slave.c:676
The allocated array of pointers to keep slave configuration was not freed.

void
vMBTCPPortDisable( void )
{
    vTaskSuspend(xConfig.xMbTcpTaskHandle);
    for (int i = 0; i < MB_TCP_PORT_MAX_CONN; i++) {
        MbClientInfo_t* pxClientInfo = xConfig.pxMbClientInfo[i];
        if ((pxClientInfo != NULL) && (pxClientInfo->xSockId > 0)) {
            xMBTCPPortCloseConnection(pxClientInfo);
            vMBTCPPortFreeClientInfo(pxClientInfo);
            xConfig.pxMbClientInfo[i] = NULL;
        }
    }
    free(xConfig.pxMbClientInfo); // <<<<<<<< Free array of slave configuration pointers
    close(xListenSock);
    xListenSock = -1;
    vMBTCPPortRespQueueDelete(xConfig.xRespQueueHandle);
}     

There are still some leaks in LWIP but after a couple init/destroy cycles the heap size gets stable (log below):

I (6516) RTOS:     total_free_bytes:     init:  252856
W (7516) SLAVE_TEST: Close Modbus...
D (7516) MB_PORT_COMMON: vMBPortSetMode: Port enter critical.
D (7516) MB_PORT_COMMON: vMBPortSetMode: Port exit critical
I (7526) RTOS:     total_free_bytes:      destroyed: 258576
W (8526) SLAVE_TEST: Start Modbus...
D (8526) MB_PORT_COMMON: vMBPortSetMode: Port enter critical.
D (8526) MB_PORT_COMMON: vMBPortSetMode: Port exit critical
I (8526) MB_TCP_SLAVE_PORT: Protocol stack initialized.
I (8536) MB_TCP_SLAVE_PORT: Socket (#54), listener  on port: 502, errno=0
I (8586) RTOS:     total_free_bytes:     init:  252732
W (9586) SLAVE_TEST: Close Modbus...
D (9586) MB_PORT_COMMON: vMBPortSetMode: Port enter critical.
D (9586) MB_PORT_COMMON: vMBPortSetMode: Port exit critical
I (9586) RTOS:     total_free_bytes:      destroyed: 258480
W (10596) SLAVE_TEST: Start Modbus...
D (10596) MB_PORT_COMMON: vMBPortSetMode: Port enter critical.
D (10596) MB_PORT_COMMON: vMBPortSetMode: Port exit critical
I (10596) MB_TCP_SLAVE_PORT: Protocol stack initialized.
I (10606) MB_TCP_SLAVE_PORT: Socket (#54), listener  on port: 502, errno=0
I (10656) RTOS:     total_free_bytes:     init:  252716
W (11656) SLAVE_TEST: Close Modbus...
D (11656) MB_PORT_COMMON: vMBPortSetMode: Port enter critical.
D (11656) MB_PORT_COMMON: vMBPortSetMode: Port exit critical
I (11656) RTOS:     total_free_bytes:      destroyed: 258484
W (12666) SLAVE_TEST: Start Modbus...
D (12666) MB_PORT_COMMON: vMBPortSetMode: Port enter critical.
D (12666) MB_PORT_COMMON: vMBPortSetMode: Port exit critical
I (12666) MB_TCP_SLAVE_PORT: Protocol stack initialized.
I (12676) MB_TCP_SLAVE_PORT: Socket (#54), listener  on port: 502, errno=0
I (12726) RTOS:     total_free_bytes:     init:  252732
W (13726) SLAVE_TEST: Close Modbus...
D (13726) MB_PORT_COMMON: vMBPortSetMode: Port enter critical.
D (13726) MB_PORT_COMMON: vMBPortSetMode: Port exit critical
I (13726) RTOS:     total_free_bytes:      destroyed: 258492
W (14736) SLAVE_TEST: Start Modbus...
D (14736) MB_PORT_COMMON: vMBPortSetMode: Port enter critical.
D (14736) MB_PORT_COMMON: vMBPortSetMode: Port exit critical
I (14736) MB_TCP_SLAVE_PORT: Protocol stack initialized.
I (14746) MB_TCP_SLAVE_PORT: Socket (#54), listener  on port: 502, errno=0
I (14796) RTOS:     total_free_bytes:     init:  252732
W (15796) SLAVE_TEST: Close Modbus...
D (15796) MB_PORT_COMMON: vMBPortSetMode: Port enter critical.
D (15796) MB_PORT_COMMON: vMBPortSetMode: Port exit critical
I (15796) RTOS:     total_free_bytes:      destroyed: 258492
W (16806) SLAVE_TEST: Start Modbus...
D (16806) MB_PORT_COMMON: vMBPortSetMode: Port enter critical.
D (16806) MB_PORT_COMMON: vMBPortSetMode: Port exit critical
I (16806) MB_TCP_SLAVE_PORT: Protocol stack initialized.
I (16816) MB_TCP_SLAVE_PORT: Socket (#54), listener  on port: 502, errno=0
I (16866) RTOS:     total_free_bytes:     init:  252732
W (17866) SLAVE_TEST: Close Modbus...
D (17866) MB_PORT_COMMON: vMBPortSetMode: Port enter critical.
D (17866) MB_PORT_COMMON: vMBPortSetMode: Port exit critical
I (17866) RTOS:     total_free_bytes:      destroyed: 258492

Please check this on your side. Thanks.

@oachkatzalschwoaf
Copy link
Author

Thanks @alisitsyn

I've tested Heap Tracing feature for the first time last night - wasn't sure about the result, as i just got 7 entries, 6 of them: 0x400e5358: mem_malloc at C:/esp/esp-idf/components/lwip/lwip/src/core/mem.c:237

and a single xMBTCPPortInit

7 allocations trace (1000 entry buffer)
24 bytes (@ 0x3ffdecd8) allocated CPU 0 ccount 0x4c28cf28 caller 0x400d8c06:0x400d7b39:0x400d7981:0x400d77bf:0x400d6c69:0x400d6816:0x400d692
0x400d8c06: xMBTCPPortInit at C:/esp/esp-idf/components/freemodbus/tcp_slave/port/port_tcp_slave.c:130

but each time 1 missed free with 120byte leaked

120 bytes 'leaked' in trace (7 allocations)
total allocations 90 total frees 89

but after adding
free(xConfig.pxMbClientInfo); // <<<<<<<< Free array of slave configuration pointers

I also get the same result.

With these changes the issue is fixed for me.

@alisitsyn
Copy link
Collaborator

@oachkatzalschwoaf ,

Thank you for update. I guess we use different commits. The leak was in 0x400d8c06: xMBTCPPortInit components/freemodbus/tcp_slave/port/port_tcp_slave.c:138 on my side. The fix above helps to free the xConfig.pxMbClientInfo and the leak is gone as per log on my side.

alisitsyn pushed a commit to alisitsyn/esp-idf that referenced this issue Jan 19, 2022
@espressif-bot espressif-bot added Status: In Progress Work is in progress and removed Status: Opened Issue is new labels Jan 24, 2022
@espressif-bot espressif-bot added Resolution: NA Issue resolution is unavailable Status: Done Issue is done internally Resolution: Done Issue is done internally and removed Status: In Progress Work is in progress Resolution: NA Issue resolution is unavailable labels Mar 3, 2022
@Alvin1Zhang
Copy link
Collaborator

Thanks for reporting and sorry for slow turnaround, fix on master branch is available at dcaac79.

espressif-bot pushed a commit that referenced this issue Mar 9, 2022
espressif-bot pushed a commit that referenced this issue Mar 13, 2022
@Alvin1Zhang
Copy link
Collaborator

Thanks for reporting, fixes on release/4.4 and release/4.3 are available, feel free to reopen if the issue still happens. Thanks.

@dabbinavo
Copy link
Contributor

dabbinavo commented Apr 6, 2022

Hello @Alvin1Zhang, @alisitsyn and @oachkatzalschwoaf,

i run into the exact same issue, but i am on release/4.4, where this issue normally shouldn't exist anymore?!

Looking in the file system, my esp-idf contains the changes of commit dcaac79 linked by @Alvin1Zhang

I am not sure if I have to open a new issue or if this issue gets reopened again.

Steps to reproduce the issue:

  1. Create new project based on esp-idf/examples/protocols/modbus/tcp/mb_tcp_slave/
  2. Setup environment to use esp-idf release/4.4 (i am using vscode with the espressif plugin)
  3. Starting SDK Configuration
    1. Set WiFi Credentials
    2. Set log verbosity to Info
  4. Modify app_main to
    void app_main(void)
    {
        ESP_ERROR_CHECK(init_services());
    
        // Set UART log level
        esp_log_level_set(SLAVE_TAG, ESP_LOG_INFO);
    
        mb_communication_info_t comm_info = { 0 };
    
    #if !CONFIG_EXAMPLE_CONNECT_IPV6
        comm_info.ip_addr_type = MB_IPV4;
    #else
        comm_info.ip_addr_type = MB_IPV6;
    #endif
        comm_info.ip_mode = MB_MODE_TCP;
    
        comm_info.ip_port = MB_TCP_PORT_NUMBER;
        ESP_ERROR_CHECK(slave_init(&comm_info));
    
        while(1){
            vTaskDelay(1000/portTICK_PERIOD_MS);
            ESP_LOGW(SLAVE_TAG, "Close Modbus...");
            slave_destroy();
            ESP_LOGI("RTOS", "    total_free_bytes:      destroyed: %d", heap_caps_get_free_size(MALLOC_CAP_INTERNAL));
            vTaskDelay(100/portTICK_PERIOD_MS);
            ESP_LOGW(SLAVE_TAG, "Start Modbus...");
            slave_init(&comm_info);
            ESP_LOGI("RTOS", "    total_free_bytes:     init:  %d", heap_caps_get_free_size(MALLOC_CAP_INTERNAL));
        }
    
        // The Modbus slave logic is located in this function (user handling of Modbus)
        slave_operation_func(NULL);
    
        ESP_ERROR_CHECK(slave_destroy());
        ESP_ERROR_CHECK(destroy_services());
    }
  5. Running the example leads to the following log output:
    entry 0x40080694
    I (28) boot: ESP-IDF v4.4 2nd stage bootloader
    I (28) boot: compile time 16:04:12
    I (28) boot: chip revision: 1
    I (31) boot_comm: chip revision: 1, min. bootloader chip revision: 0
    I (38) boot.esp32: SPI Speed      : 40MHz
    I (43) boot.esp32: SPI Mode       : DIO
    I (47) boot.esp32: SPI Flash Size : 4MB
    I (52) boot: Enabling RNG early entropy source...
    I (57) boot: Partition Table:
    I (61) 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 (95) boot_comm: chip revision: 1, min. application chip revision: 0
    I (102) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=15df0h ( 89584) map
    I (143) esp_image: segment 1: paddr=00025e18 vaddr=3ffb0000 size=03a10h ( 14864) load
    I (149) esp_image: segment 2: paddr=00029830 vaddr=40080000 size=067e8h ( 26600) load
    I (160) esp_image: segment 3: paddr=00030020 vaddr=400d0020 size=750d4h (479444) map
    I (334) esp_image: segment 4: paddr=000a50fc vaddr=400867e8 size=0de24h ( 56868) load
    I (357) esp_image: segment 5: paddr=000b2f28 vaddr=50000000 size=00010h (    16) load
    I (368) boot: Loaded app from partition at offset 0x10000
    I (368) boot: Disabling RNG early entropy source...
    I (380) cpu_start: Pro cpu up.
    I (380) cpu_start: Starting app cpu, entry point is 0x400811d8
    0x400811d8: call_start_cpu1 at /path/to/esp-idf/components/esp_system/port/cpu_start.c:156
    
    I (0) cpu_start: App cpu up.
    I (394) cpu_start: Pro cpu start user code
    I (394) cpu_start: cpu freq: 160000000
    I (394) cpu_start: Application information:
    I (399) cpu_start: Project name:     modbus_tcp_slave
    I (404) cpu_start: App version:      1
    I (409) cpu_start: Compile time:     Apr  6 2022 16:03:30
    I (415) cpu_start: ELF file SHA256:  dfb0b69e4e791cd1...
    I (421) cpu_start: ESP-IDF:          v4.4
    I (426) heap_init: Initializing. RAM available for dynamic allocation:
    I (433) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
    I (439) heap_init: At 3FFB7AE8 len 00028518 (161 KiB): DRAM
    I (445) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
    I (451) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
    I (458) heap_init: At 4009460C len 0000B9F4 (46 KiB): IRAM
    I (465) spi_flash: detected chip: generic
    I (469) spi_flash: flash io: dio
    I (474) cpu_start: Starting scheduler on PRO CPU.
    I (0) cpu_start: Starting scheduler on APP CPU.
    I (533) wifi:wifi driver task: 3ffc06b0, prio:23, stack:6656, core=0
    I (533) system_api: Base MAC address is not set
    I (533) system_api: read default base MAC address from EFUSE
    I (543) wifi:wifi firmware version: 7679c42
    I (543) wifi:wifi certification version: v7.0
    I (543) wifi:config NVS flash: enabled
    I (543) wifi:config nano formating: disabled
    I (553) wifi:Init data frame dynamic rx buffer num: 32
    I (553) wifi:Init management frame dynamic rx buffer num: 32
    I (563) wifi:Init management short buffer num: 32
    I (563) wifi:Init dynamic tx buffer num: 32
    I (573) wifi:Init static rx buffer size: 1600
    I (573) wifi:Init static rx buffer num: 10
    I (573) wifi:Init dynamic rx buffer num: 32
    I (583) wifi_init: rx ba win: 6
    I (583) wifi_init: tcpip mbox: 32
    I (593) wifi_init: udp mbox: 6
    I (593) wifi_init: tcp mbox: 6
    I (593) wifi_init: tcp tx win: 5744
    I (603) wifi_init: tcp rx win: 5744
    I (603) wifi_init: tcp mss: 1440
    I (613) wifi_init: WiFi IRAM OP enabled
    I (613) wifi_init: WiFi RX IRAM OP enabled
    I (623) example_connect: Connecting to ********...
    I (623) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
    I (723) wifi:mode : sta (24:0a:c4:4e:af:c8)
    I (733) wifi:enable tsf
    I (733) example_connect: Waiting for IP(s)
    I (2783) wifi:new:<6,0>, old:<1,0>, ap:<255,255>, sta:<6,0>, prof:1
    I (3553) wifi:state: init -> auth (b0)
    I (3553) wifi:state: auth -> assoc (0)
    I (3563) wifi:state: assoc -> run (10)
    I (3563) wifi:connected with ********, aid = 3, channel 6, BW20, bssid = 64:09:ac:ba:2a:e7
    I (3563) wifi:security: WPA2-PSK, phy: bgn, rssi: -61
    I (3573) wifi:pm start, type: 1
    
    I (3573) wifi:AP's beacon interval = 102400 us, DTIM period = 1
    I (4523) esp_netif_handlers: example_connect: sta ip: 192.168.1.106, mask: 255.255.255.0, gw: 192.168.1.1
    I (4523) example_connect: Got IPv4 event: Interface "example_connect: sta" address: 192.168.1.106
    I (4533) example_connect: Connected to example_connect: sta
    I (4533) example_connect: - IPv4 address: 192.168.1.106
    I (4543) wifi:Set ps type: 0
    
    I (4543) MB_TCP_SLAVE_PORT: Protocol stack initialized.
    I (4553) MB_TCP_SLAVE_PORT: Socket (#54), listener  on port: 502, errno=0
    W (5613) SLAVE_TEST: Close Modbus...
    I (5613) RTOS:     total_free_bytes:      destroyed: 274468
    W (5713) SLAVE_TEST: Start Modbus...
    Guru Meditation Error: Core  0 panic'ed (StoreProhibited). Exception was unhandled.
    
    Core  0 register dump:
    PC      : 0x4008cf9e  PS      : 0x00060b33  A0      : 0x8008da4c  A1      : 0x3ffbaf00
    0x4008cf9e: remove_free_block at /path/to/esp-idf/components/heap/heap_tlsf.c:213
     (inlined by) block_locate_free at /path/to/esp-idf/components/heap/heap_tlsf.c:448
     (inlined by) tlsf_malloc at /path/to/esp-idf/components/heap/heap_tlsf.c:757
    
    A2      : 0x3ffb7afc  A3      : 0x00000018  A4      : 0x00000000  A5      : 0x3ffc834c
    A6      : 0x00000000  A7      : 0x3ffc5ebc  A8      : 0x3ffc5e98  A9      : 0x00000019
    A10     : 0x00000002  A11     : 0x00000000  A12     : 0x00000003  A13     : 0x00060b23
    A14     : 0x3f415e10  A15     : 0x00000100  SAR     : 0x0000001a  EXCCAUSE: 0x0000001d
    EXCVADDR: 0x0000000f  LBEG    : 0x4000c2e0  LEND    : 0x4000c2f6  LCOUNT  : 0x00000000
    
    
    Backtrace:0x4008cf9b:0x3ffbaf000x4008da49:0x3ffbaf20 0x40081c0d:0x3ffbaf40 0x400d7483:0x3ffbaf60 0x400d69bd:0x3ffbafa0 0x400d6bab:0x3ffbaff0 0x401438c5:0x3ffbb030 0x4008b735:0x3ffbb050
    0x4008cf9b: remove_free_block at /path/to/esp-idf/components/heap/heap_tlsf.c:212
     (inlined by) block_locate_free at /path/to/esp-idf/components/heap/heap_tlsf.c:448
     (inlined by) tlsf_malloc at /path/to/esp-idf/components/heap/heap_tlsf.c:757
    
    0x4008da49: multi_heap_malloc_impl at /path/to/esp-idf/components/heap/multi_heap.c:197
    
    0x40081c0d: heap_caps_malloc at /path/to/esp-idf/components/heap/heap_caps.c:145
    
    0x400d7483: mbc_slave_set_descriptor at /path/to/esp-idf/components/freemodbus/common/esp_modbus_slave.c:226 (discriminator 2)
    
    0x400d69bd: slave_init at C:\Users\<user>\esp-modbus-slave\mb_tcp_slave\build/../main/tcp_slave.c:341 (discriminator 2)
    
    0x400d6bab: app_main at C:\Users\<user>\esp-modbus-slave\mb_tcp_slave\build/../main/tcp_slave.c:445 (discriminator 2)
    
    0x401438c5: main_task at /path/to/esp-idf/components/freertos/port/port_common.c:129 (discriminator 2)
    
    0x4008b735: vPortTaskWrapper at /path/to/esp-idf/components/freertos/port/xtensa/port.c:131
    
    
    
    
    
    ELF file SHA256: dfb0b69e4e791cd1
    
    Rebooting...
    ets Jun  8 2016 00:22:57
    
    rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
    configsip: 0, SPIWP:0xee
    clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
    mode:DIO, clock div:2
    load:0x3fff0030,len:6604
    ho 0 tail 12 room 4
    load:0x40078000,len:14780
    load:0x40080400,len:3792
    0x40080400: _init at ??:?
    
    entry 0x40080694
    I (29) boot: ESP-IDF v4.4 2nd stage bootloader
    ... (endless loop now repeating the same output)
    

@alisitsyn
Copy link
Collaborator

alisitsyn commented Apr 6, 2022

Hello @dabbinavo,

This issue has been corrected. I will check it soon. I will let you know when having some details.

@dabbinavo
Copy link
Contributor

dabbinavo commented Apr 7, 2022

Hello @alisitsyn,

ok, thanks for the hint! Now i found the other commit that fixes the issue on the release/v4.4 branch:

Switching to the latest commit on release/v4.4 instead of using the tag v4.4 solves the issue. Didn't realize that the issue was fixed after the release of v4.4..

Seems that we have to wait for v4.4.1 to have the fix in an official release.

@alisitsyn
Copy link
Collaborator

alisitsyn commented Apr 7, 2022

Hello dabbinavo,

I just recently checked this and found the fix in commit ba9c0c2 as well. The example works just fine on my side with release/v4.4 branch. The log:

0x400d7148: on_got_ip at /home/esp-man/esp32/esp-idf/examples/common_components/protocol_examples_common/connect.c:167

I (5472) example_connect: Got IPv4 event: Interface "example_connect: sta" address: 192.168.1.8
I (5482) example_connect: Connected to example_connect: sta
D (5492) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x3ffc53a4
I (5492) example_connect: - IPv4 address: 192.168.1.8
I (5502) wifi:Set ps type: 0

D (5502) MB_PORT_COMMON: vMBPortSetMode: Port enter critical.
D (5512) MB_PORT_COMMON: vMBPortSetMode: Port exit critical
I (5512) MB_TCP_SLAVE_PORT: Protocol stack initialized.
D (5522) MB_PORT_COMMON: TCP Slave port enable.
I (5532) MB_TCP_SLAVE_PORT: Socket (#54), listener  on port: 502, errno=0
W (6582) SLAVE_TEST: Close Modbus...
D (6582) MB_PORT_COMMON: TCP Slave port disable.
D (6582) MB_PORT_COMMON: vMBPortSetMode: Port enter critical.
D (6582) MB_PORT_COMMON: vMBPortSetMode: Port exit critical
I (6582) RTOS:     total_free_bytes:      destroyed: 272184
W (6692) SLAVE_TEST: Start Modbus...
D (6692) MB_PORT_COMMON: vMBPortSetMode: Port enter critical.
D (6692) MB_PORT_COMMON: vMBPortSetMode: Port exit critical
I (6692) MB_TCP_SLAVE_PORT: Protocol stack initialized.
D (6702) MB_PORT_COMMON: TCP Slave port enable.
I (6702) MB_TCP_SLAVE_PORT: Socket (#54), listener  on port: 502, errno=0
I (6762) RTOS:     total_free_bytes:     init:  266392
W (7762) SLAVE_TEST: Close Modbus...
D (7762) MB_PORT_COMMON: TCP Slave port disable.
D (7762) MB_PORT_COMMON: vMBPortSetMode: Port enter critical.
D (7762) MB_PORT_COMMON: vMBPortSetMode: Port exit critical
I (7762) RTOS:     total_free_bytes:      destroyed: 272184
W (7872) SLAVE_TEST: Start Modbus...
D (7872) MB_PORT_COMMON: vMBPortSetMode: Port enter critical.
D (7872) MB_PORT_COMMON: vMBPortSetMode: Port exit critical
I (7872) MB_TCP_SLAVE_PORT: Protocol stack initialized.
D (7882) MB_PORT_COMMON: TCP Slave port enable.
I (7882) MB_TCP_SLAVE_PORT: Socket (#54), listener  on port: 502, errno=0
I (7942) RTOS:     total_free_bytes:     init:  266380
W (8942) SLAVE_TEST: Close Modbus...
D (8942) MB_PORT_COMMON: TCP Slave port disable.
D (8942) MB_PORT_COMMON: vMBPortSetMode: Port enter critical.
D (8942) MB_PORT_COMMON: vMBPortSetMode: Port exit critical
I (8942) RTOS:     total_free_bytes:      destroyed: 272184
W (9052) SLAVE_TEST: Start Modbus...
D (9052) MB_PORT_COMMON: vMBPortSetMode: Port enter critical.
D (9052) MB_PORT_COMMON: vMBPortSetMode: Port exit critical
I (9052) MB_TCP_SLAVE_PORT: Protocol stack initialized.
D (9062) MB_PORT_COMMON: TCP Slave port enable.
I (9062) MB_TCP_SLAVE_PORT: Socket (#54), listener  on port: 502, errno=0
I (9122) RTOS:     total_free_bytes:     init:  266392
W (10122) SLAVE_TEST: Close Modbus...
D (10122) MB_PORT_COMMON: TCP Slave port disable.
D (10122) MB_PORT_COMMON: vMBPortSetMode: Port enter critical.
D (10122) MB_PORT_COMMON: vMBPortSetMode: Port exit critical
I (10122) RTOS:     total_free_bytes:      destroyed: 272184
W (10232) SLAVE_TEST: Start Modbus...
D (10232) MB_PORT_COMMON: vMBPortSetMode: Port enter critical.
D (10232) MB_PORT_COMMON: vMBPortSetMode: Port exit critical
I (10232) MB_TCP_SLAVE_PORT: Protocol stack initialized.
D (10242) MB_PORT_COMMON: TCP Slave port enable.
I (10242) MB_TCP_SLAVE_PORT: Socket (#54), listener  on port: 502, errno=0
I (10302) RTOS:     total_free_bytes:     init:  266364
W (11302) SLAVE_TEST: Close Modbus...
D (11302) MB_PORT_COMMON: TCP Slave port disable.
D (11302) MB_PORT_COMMON: vMBPortSetMode: Port enter critical.
D (11302) MB_PORT_COMMON: vMBPortSetMode: Port exit critical
I (11302) RTOS:     total_free_bytes:      destroyed: 272184
W (11412) SLAVE_TEST: Start Modbus...
D (11412) MB_PORT_COMMON: vMBPortSetMode: Port enter critical.
D (11412) MB_PORT_COMMON: vMBPortSetMode: Port exit critical
I (11412) MB_TCP_SLAVE_PORT: Protocol stack initialized.
D (11422) MB_PORT_COMMON: TCP Slave port enable.
I (11422) MB_TCP_SLAVE_PORT: Socket (#54), listener  on port: 502, errno=0
I (11482) RTOS:     total_free_bytes:     init:  266364
W (12482) SLAVE_TEST: Close Modbus...
D (12482) MB_PORT_COMMON: TCP Slave port disable.
D (12482) MB_PORT_COMMON: vMBPortSetMode: Port enter critical.
D (12482) MB_PORT_COMMON: vMBPortSetMode: Port exit critical
I (12482) RTOS:     total_free_bytes:      destroyed: 272184
W (12592) SLAVE_TEST: Start Modbus...
D (12592) MB_PORT_COMMON: vMBPortSetMode: Port enter critical.
D (12592) MB_PORT_COMMON: vMBPortSetMode: Port exit critical
I (12592) MB_TCP_SLAVE_PORT: Protocol stack initialized.
D (12602) MB_PORT_COMMON: TCP Slave port enable.
I (12602) MB_TCP_SLAVE_PORT: Socket (#54), listener  on port: 502, errno=0
I (12662) RTOS:     total_free_bytes:     init:  266364
W (13662) SLAVE_TEST: Close Modbus...
D (13662) MB_PORT_COMMON: TCP Slave port disable.
D (13662) MB_PORT_COMMON: vMBPortSetMode: Port enter critical.
D (13662) MB_PORT_COMMON: vMBPortSetMode: Port exit critical
I (13662) RTOS:     total_free_bytes:      destroyed: 272184
W (13772) SLAVE_TEST: Start Modbus...
D (13772) MB_PORT_COMMON: vMBPortSetMode: Port enter critical.
D (13772) MB_PORT_COMMON: vMBPortSetMode: Port exit critical
I (13772) MB_TCP_SLAVE_PORT: Protocol stack initialized.
D (13782) MB_PORT_COMMON: TCP Slave port enable.
I (13782) MB_TCP_SLAVE_PORT: Socket (#54), listener  on port: 502, errno=0
I (13842) RTOS:     total_free_bytes:     init:  266364
W (14842) SLAVE_TEST: Close Modbus...
D (14842) MB_PORT_COMMON: TCP Slave port disable.
D (14842) MB_PORT_COMMON: vMBPortSetMode: Port enter critical.
D (14842) MB_PORT_COMMON: vMBPortSetMode: Port exit critical
I (14842) RTOS:     total_free_bytes:      destroyed: 272184
W (14952) SLAVE_TEST: Start Modbus...
D (14952) MB_PORT_COMMON: vMBPortSetMode: Port enter critical.
D (14952) MB_PORT_COMMON: vMBPortSetMode: Port exit critical
I (14952) MB_TCP_SLAVE_PORT: Protocol stack initialized.
D (14962) MB_PORT_COMMON: TCP Slave port enable.
I (14962) MB_TCP_SLAVE_PORT: Socket (#54), listener  on port: 502, errno=0
I (15022) RTOS:     total_free_bytes:     init:  266388
W (16022) SLAVE_TEST: Close Modbus...
D (16022) MB_PORT_COMMON: TCP Slave port disable.
D (16022) MB_PORT_COMMON: vMBPortSetMode: Port enter critical.
D (16022) MB_PORT_COMMON: vMBPortSetMode: Port exit critical
I (16022) RTOS:     total_free_bytes:      destroyed: 272184

Didn't realize that the issue was fixed after the release of v4.4..

This was planned to be merged in v4.4 but delays often happen...

@Alvin1Zhang
Copy link
Collaborator

Thanks for reporting and sharing the feedback, will update once IDF v4.4.1 releases, thanks.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Resolution: Done Issue is done internally Status: Done Issue is done internally
Projects
None yet
Development

No branches or pull requests

5 participants