mdt_erase success, but vfs_format resets board (esp32-heltec-lora32-v2)

[remiphilippe]

Description

Cannot format using vfs_format on Heltec Lora v2 (esp32-heltec-lora32-v2)

Steps to reproduce the issue

I'm following the SPIFFs example (https://github.com/RIOT-OS/RIOT/tree/master/examples/filesystem) and test (https://github.com/RIOT-OS/RIOT/blob/master/tests/pkg_spiffs/main.c)

Makefile (content related to fs):

BOARD ?= esp32-heltec-lora32-v2
# filesystem
USEMODULE += mtd
USEMODULE += vfs
USEMODULE += esp_spiffs

Code (related to fs):

#define _dev (MTD_0)

/* Flash mount point */
#define FLASH_MOUNT_POINT   "/sda"

/* include file system header */
#include "vfs.h"
#include "mtd.h"
#include "fs/spiffs_fs.h"

/* file system specific descriptor
 * as for littlefs, some fields can be changed if needed,
 * this example focus on basic usage, i.e. entire memory used */
static spiffs_desc_t spiffs_desc = {
    .lock = MUTEX_INIT,
};

static vfs_mount_t spiffs_mount = {
    .fs = &spiffs_file_system,
    .mount_point = FLASH_MOUNT_POINT,
    .private_data = &spiffs_desc,
};

/* Command handlers */
static int _mount(int argc, char **argv)
{
    (void)argc;
    (void)argv;
    int res = vfs_mount(&spiffs_mount);
    if (res < 0) {
        printf("Error while mounting %s...try format\n", FLASH_MOUNT_POINT);
        return 1;
    }

    printf("%s successfully mounted\n", FLASH_MOUNT_POINT);
    return 0;
}

static int _format(int argc, char **argv)
{
    (void)argc;
    (void)argv;
    // struct statvfs vstat;

    // if(vfs_statvfs(FLASH_MOUNT_POINT, &vstat) < 0) {
    //     printf("Error stat for %s\n", FLASH_MOUNT_POINT);
    //     //return 1;
    // } else {
    //     printf("FSID: %lu\n", vstat.f_fsid);
    // }

    printf("erasing mtd...\t");
    if(mtd_erase(_dev, 0, _dev->page_size * _dev->pages_per_sector * _dev->sector_count) != 0) {
        puts("[Failed]");
        return 1;
    } else {
        puts("[OK]");
    }

    printf("formating %s....\t", FLASH_MOUNT_POINT);
    if(vfs_format(&spiffs_mount) < 0) {
        puts("[Failed]");
        return 1;
    } else {
        puts("[OK]");
    }

    return 0;
}

In main I also defined: spiffs_desc.dev = _dev;

Expected results

memory gets formated, system doesn't reboot

Actual results

mdt_erase works fine, but there seems to be a crash (or a WDT reset I'm not 100% sure), in any case the board resets

2020-07-13 11:47:43,420 #  format
2020-07-13 11:48:04,169 # erasing mtd...	[OK]
2020-07-13 11:48:04,283 # �������������������������������������������������������������������������������������������������������������������������������������������������������00000000	�����������������������������������������������������������������������������������������������������000000a0	formating /sda....		pid | name                 | state    Q | pri | stack  ( used) ( free) | base addr  | current     
2020-07-13 11:48:04,292 # 	  - | isr_stack            | -        - |   - |   2048 (  832) ( 1216) | 0x3ffb0220 | 0x3ffb0a20
2020-07-13 11:48:04,301 # 	  1 | wifi-event-loop      | bl rx    _ |   4 |   2104 (  804) ( 1300) | 0x3ffaefcc | 0x3ffaf5e0 
2020-07-13 11:48:04,309 # 	  2 | idle                 | pending  Q |  31 |   2048 (  476) ( 1572) | 0x3ffb4d6c | 0x3ffb53b0 
2020-07-13 11:48:04,318 # 	  3 | main                 | running  Q |  15 |   3072 ( 1260) ( 1812) | 0x3ffb556c | 0x3ffb5c80 
2020-07-13 11:48:04,330 # 	  4 | ipv6                 | bl rx    _ |  12 |   2048 (  720) ( 1328) | 0x3ffb77d0 | 0x3ffb7d70 
2020-07-13 11:48:04,335 # 	  5 | udp                  | bl rx    _ |  13 |   2048 (  580) ( 1468) | 0x3ffba454 | 0x3ffbaa10 
2020-07-13 11:48:04,344 # 	  6 | wifi                 | bl rx    _ |   1 |   3128 ( 1860) ( 1268) | 0x3ffbe7cc | 0x3ffbf1d0 
2020-07-13 11:48:04,352 # 	  7 | netif-esp-wifi       | bl rx    _ |  10 |   2048 (  912) ( 1136) | 0x3ffbb1a0 | 0x3ffbb730 
2020-07-13 11:48:04,361 # 	  8 | sx127x               | bl rx    _ |  10 |   2048 (  792) ( 1256) | 0x3ffb83a8 | 0x3ffb8940 
2020-07-13 11:48:04,367 # 	    | SUM                  |            |     |  20592 ( 8236) (12356)
2020-07-13 11:48:04,368 # 
2020-07-13 11:48:04,642 # heap: 143488 (used 28860, free 114628) ����������������������������������������������������������������������������������������������������������������������������������������������������������������3f4023a9	�����������������������������������������������������������������������������������������00000001	��������������������������������������������������������������������������400d2ae1	����������������������������������������������������������00060032	������������������������������������������00000000	��������������������������00000000	����������400d2ae1	epc2    : 40062258	epc3    : 00000000	epc4    : 00000000
2020-07-13 11:48:04,647 # epc5    : 00000000	epc6    : 00000000	epc7    : 00000000	
2020-07-13 11:48:04,650 # a0      : 80081d68	a1      : 3ffb09d0	a2      : 00000001	a3      : 00000000
2020-07-13 11:48:04,662 # a4      : 3ffb29d0	a5      : 3ffb5e50	a6      : 3ffb23e0	a7      : 3ffb5ee0
2020-07-13 11:48:04,666 # a8      : 000000fe	a9      : 00000002	a10     : 000002aa	a11     : 3ffb5e30
2020-07-13 11:48:04,669 # a12     : 80094011	a13     : 3ffb5e10	a14     : 001000fc	a15     : 3ffb5ee0
2020-07-13 11:48:04,671 # lbeg    : 40096c30	lend    : 40096c3a	lcount  : 00000000
2020-07-13 11:48:10,168 # W (5) boot: PRO CPU has been reset by WDT.
2020-07-13 11:48:10,173 # W (5) boot: WDT reset info: PRO CPU PC=0x4008c3ec
2020-07-13 11:48:10,177 # W (5) boot: WDT reset info: APP CPU PC=0xd4fe9c80
2020-07-13 11:48:10,422 # 
2020-07-13 11:48:10,602 # phy_version: 3910, c0c45a3, May 21 2018, 18:07:06, 0, 2
2020-07-13 11:48:10,611 # main(): This is RIOT! (Version: 2020.07-devel-1775-gc56147)

Versions

BUILD_IN_DOCKER=1
Master Branch on commit: c56147d33e234bd5e7186b905e3a073a50c9b8ac
Docker Image details:

[
    {
        "Id": "sha256:8b15f9c3a57c177242c6ceee2dce4d7aab02f1488116fed0c7694f8d5f5eb282",
        "RepoTags": [
            "riot/riotbuild:latest"
        ],
        "RepoDigests": [
            "riot/riotbuild@sha256:0695d78762a9c846ce0a56b4ec9f8a6cd9aeccca883b773ad820543b747949ba"
        ],
        "Parent": "",
        "Comment": "",
        "Created": "2020-06-22T08:48:34.816055737Z",
        "Container": "fceb8fce663a5b6582932d34f8c2d87e770f91077bbc10b93c2ec698a1df0b01",
        "ContainerConfig": {
            "Hostname": "fceb8fce663a",
            "Domainname": "",
            "User": "",
            "AttachStdin": false,
            "AttachStdout": false,
            "AttachStderr": false,
            "Tty": false,
            "OpenStdin": false,
            "StdinOnce": false,
            "Env": [
                "PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/opt/gcc-arm-none-eabi-9-2019-q4-major/bin:/opt/mips-mti-elf/2018.09-03/bin:/opt/gnu-mcu-eclipse/riscv-none-gcc/8.2.0-2.2-20190521-0004/bin:/opt/esp/esp-open-sdk/xtensa-lx106-elf/bin:/opt/esp/xtensa-esp8266-elf/bin:/opt/esp/xtensa-esp32-elf/bin:/opt/riot-toolchain/msp430-elf/9.2.0-15/bin",
                "DEBIAN_FRONTEND=noninteractive",
                "LC_ALL=C.UTF-8",
                "LANG=C.UTF-8",
                "MIPS_ELF_ROOT=/opt/mips-mti-elf/2018.09-03",
                "ESP8266_SDK_DIR=/opt/esp/esp-open-sdk/sdk",
                "ESP8266_NEWLIB_DIR=/opt/esp/newlib-xtensa",
                "ESP8266_RTOS_SDK_DIR=/opt/esp/ESP8266_RTOS_SDK"
            ],
            "Cmd": [
                "/bin/sh",
                "-c",
                "#(nop) WORKDIR /data/riotbuild"
            ],
            "Image": "sha256:23f247a00510072e4d6905803b61431a56fdf7b1a16914964dc7cb6874db2a62",
            "Volumes": null,
            "WorkingDir": "/data/riotbuild",
            "Entrypoint": [
                "/bin/bash",
                "/run.sh"
            ],
            "OnBuild": null,
            "Labels": {
                "maintainer": "Kaspar Schleiser <[email protected]>"
            }
        },
        "DockerVersion": "19.03.8",
        "Author": "",
        "Config": {
            "Hostname": "",
            "Domainname": "",
            "User": "",
            "AttachStdin": false,
            "AttachStdout": false,
            "AttachStderr": false,
            "Tty": false,
            "OpenStdin": false,
            "StdinOnce": false,
            "Env": [
                "PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/opt/gcc-arm-none-eabi-9-2019-q4-major/bin:/opt/mips-mti-elf/2018.09-03/bin:/opt/gnu-mcu-eclipse/riscv-none-gcc/8.2.0-2.2-20190521-0004/bin:/opt/esp/esp-open-sdk/xtensa-lx106-elf/bin:/opt/esp/xtensa-esp8266-elf/bin:/opt/esp/xtensa-esp32-elf/bin:/opt/riot-toolchain/msp430-elf/9.2.0-15/bin",
                "DEBIAN_FRONTEND=noninteractive",
                "LC_ALL=C.UTF-8",
                "LANG=C.UTF-8",
                "MIPS_ELF_ROOT=/opt/mips-mti-elf/2018.09-03",
                "ESP8266_SDK_DIR=/opt/esp/esp-open-sdk/sdk",
                "ESP8266_NEWLIB_DIR=/opt/esp/newlib-xtensa",
                "ESP8266_RTOS_SDK_DIR=/opt/esp/ESP8266_RTOS_SDK"
            ],
            "Cmd": [
                "/bin/bash"
            ],
            "Image": "sha256:23f247a00510072e4d6905803b61431a56fdf7b1a16914964dc7cb6874db2a62",
            "Volumes": null,
            "WorkingDir": "/data/riotbuild",
            "Entrypoint": [
                "/bin/bash",
                "/run.sh"
            ],
            "OnBuild": null,
            "Labels": {
                "maintainer": "Kaspar Schleiser <[email protected]>"
            }
        },
        "Architecture": "amd64",
        "Os": "linux",
        "Size": 4898315309,
        "VirtualSize": 4898315309,
        "GraphDriver": {
            "Data": {
                "LowerDir": "/var/lib/docker/overlay2/4cb9e627dcaaa86b076e53fa8e6956af197218bd112cd2fef7b76dc1aa0439b2/diff:/var/lib/docker/overlay2/fa6dfdd97091af40663a7648e4c673f99a6cabb9d1d17ac52ef387cfdae8789f/diff:/var/lib/docker/overlay2/700abbc73347bbad2b099f91c33d45208e4a785fbd90acaf7d653ac7bceb51a3/diff:/var/lib/docker/overlay2/86980d29ba4ef8c48bb9a226c6a6611bf63a06c602e0ec71f0ffa47b4a7ed837/diff:/var/lib/docker/overlay2/d4943e54fcabb1e8f33140866ba2cddaa4fcfebb13dbc4be766d5dc34b18a6a5/diff:/var/lib/docker/overlay2/bca1f9039d445a471c84d4ae600cb9317f41678bf65a9a20e3c853bcb8a348fc/diff:/var/lib/docker/overlay2/42948ba89731c526e4409147ec7fd448d51140f3927f7d1e20b2d3c3a9c81284/diff:/var/lib/docker/overlay2/cf12cd9d9cb508b7a990eb078f0e49c42e3d45381b912b7a09f4998c1f083f42/diff:/var/lib/docker/overlay2/9a42deed0799479087430b756a8feb59af6fc94dc8c7ae08912eeec03efc3166/diff:/var/lib/docker/overlay2/94b598d93f0ea054a845e5d67908455d5bc9006a0da6781a0aba7e56d5c097bd/diff:/var/lib/docker/overlay2/c223c526d8b24f1505a0efabc3b7f3cadfa23a8716533577b23ad138b6817c01/diff:/var/lib/docker/overlay2/e7218889fa9bf53cca4c708a0ba983bba0c4470375e681fe8829e8ae7c222f79/diff:/var/lib/docker/overlay2/cc889f185c049a7a247dd7365af6eea79fb16b99fb6e9630ff1b9c15ad537d4b/diff:/var/lib/docker/overlay2/e2e05911706f1f4f238fadec253920cc5849389e70da8bbf5ab5b64c356a8304/diff:/var/lib/docker/overlay2/de78dcfcb61668a9ca6e5048d600fea6b2d189c187d8f87460b07e95f7f45a18/diff:/var/lib/docker/overlay2/f4d573e51312adfad9e9b8c4cca32011fdf36fae25cac66855cd52c6a2052eb9/diff:/var/lib/docker/overlay2/4c812cfa20a23840d761b3a1b1b4398b0bd6c3379bcad2244f85235fb9f37e20/diff:/var/lib/docker/overlay2/c30a649fa920426d70c4be701dc3191f959c052ac6d0391c350323026bb03586/diff:/var/lib/docker/overlay2/21dea588b71ec32fe5b00ff5e1009702c4aa9f0d2947a074a68cac3d3987f807/diff",
                "MergedDir": "/var/lib/docker/overlay2/1e271148a434a2c4e87d935cc98b6538c2dfc53540a019a939965ece727f78e9/merged",
                "UpperDir": "/var/lib/docker/overlay2/1e271148a434a2c4e87d935cc98b6538c2dfc53540a019a939965ece727f78e9/diff",
                "WorkDir": "/var/lib/docker/overlay2/1e271148a434a2c4e87d935cc98b6538c2dfc53540a019a939965ece727f78e9/work"
            },
            "Name": "overlay2"
        },
        "RootFS": {
            "Type": "layers",
            "Layers": [
                "sha256:b187ff70b2e47a4cf3d735dd04b4309cb3004c3069846969716b7f804a01576b",
                "sha256:5930c9e5703fbcb1f5e47dd833763a0bb0d9b1927f97b8c5e2b7e7fb4798238e",
                "sha256:c64c52ea2c16427957eb5048da0df868d445795a5dbec8fd2b594ad169295eb0",
                "sha256:ddc500d8499442f954ee7184ef015b5041629e55bf8b336304c9614154008bcd",
                "sha256:481fa7102edea497243b81816119865829429105602b529357d5ec3efc081790",
                "sha256:f478f691ced81e48f8ee65de9edc5bf9bb4da390c3c14d9b7678ab8911005672",
                "sha256:d46b5cd0d3d2959211188b28599003c3a013a3a40b6fad32c8e5d63464a583b6",
                "sha256:47f4a94db7ec4855d150f0bb0a790c50e43beca4ebd45f9b9642b700fc8f351c",
                "sha256:b65ff9a2b045067e80ccd77de462c4e1be18925fa8220f8fd4d6da05c89c2950",
                "sha256:13162280875643f21dc040a1669af391383bdcd877a8199f66d5201e621a7633",
                "sha256:6368aa4a566f5a46d5f531ba50b62573f0b2d8887716ff53d60d39cccf29daaf",
                "sha256:22eee7ca8a2a3db73830a1d505c98ea1e16932eb290122d5913800fcb2c5a9d7",
                "sha256:95a70fcd9693785f0b3149eb53c05b2e54134092cc6c16ca110f202e3725179b",
                "sha256:88be8a29411e7fd0fc322957a96530b2814fc4ea410d2ae14c712be2b5ea4347",
                "sha256:f0c9a582de5080bb0fe5961940b25f5fb655bcfda59b212656862163d14c8e51",
                "sha256:8c6fcdad33f3be449f0b6f0f675ef165cc6eaa30f3e4aaff8d504f8362146dc6",
                "sha256:b32fe7329011273c6053f9fa8be0fe60de88ecc6065e3e1d7a9e6393b2508726",
                "sha256:cf55e64673e3c168ee1198142922aca8920d15069fee6f90b4ece8a0763732a8",
                "sha256:93e37531002a8902eb86b2bbeea573f216ada0fd683f71d050097b5b70493a90",
                "sha256:aa83b7f73175af0ae45435653fbdc5b8c82d4d81d29c55c4c8f3fc8dda0847db"
            ]
        },
        "Metadata": {
            "LastTagTime": "0001-01-01T00:00:00Z"
        }
    }
]

[remiphilippe]

Just to add, I just tried running make debug then make flash-only, and it seems to work:

> format
2020-07-13 12:07:55,316 #  format
2020-07-13 12:08:15,849 # erasing mtd...	[OK]
2020-07-13 12:10:57,513 # formating /sda....	[OK]

[remiphilippe]

It seems to exhibit the same behavior as here: #11449 (comment)

[gschorcht]

Hm, the problem described in #11449 (comment) was fixed with #12035.

Just to add, I just tried running make debug then make flash-only, and it seems to work:

This does not really make sense, since make debug does nothing for ESP32. Maybe you just observed that it crashed on the first try, but worked on the second try because the flash already had a different content.

Have you tried to erase the flash completely

dist/tools/esptool/esptool.py --port /dev/ttyUSB0 erase_flash

before you flash your program?

[gschorcht]

I'm following the SPIFFs example (https://github.com/RIOT-OS/RIOT/tree/master/examples/filesystem) and test (https://github.com/RIOT-OS/RIOT/blob/master/tests/pkg_spiffs/main.c)

Do these programs work for you with this board?

[gschorcht]

I tried your code which works for me for the board.

> format
erasing mtd...	[OK]
formating /sda....	[OK]

So I can't reproduce the problem.

[remiphilippe]

Thanks for looking into it.
It failed about 50 times before I posted here, then make debug and it worked like magic, but as you mentioned could be pure luck if make debug doesn't really impact ESP32.

I can't remember if I used the erase_flash on this board, but I can't seem to be able to reproduce since it worked.

I'll try when I order the same board again (in a week or so) and report here, for now, I think we can close this as unreproducible.