FS Mount fails on boot if not pre-formatted

[nakato]

As per the issue template for bugs, I'm bringing this to discussion first.

I've got an empty project, and I've configured an fstab for littlefs.

When I boot the MCU it locks up. If I comment out "automount" and connect and issue shell command "fs mount littlefs /lfs" it will mkfs the filesystem.

I've been able to see this on both a sparkfun_pro_micro_rp2040, and a nice_nano_v2(nrf52840) device.

/ {
        fstab {
                compatible = "zephyr,fstab";
                lfs: lfs {
                        compatible = "zephyr,fstab,littlefs";
                        mount-point = "/lfs";
                        partition = <&storage_partition>;
                        // Automount fails if partition is not already formatted, locking up the MCU
                        automount;
                        read-size = <16>;
                        prog-size = <16>;
                        cache-size = <64>;
                        lookahead-size = <32>;
                        block-cycles = <512>;
                };
        };

};

I've created a complete minimal example here: https://github.com/nakato-forks/zephyr-debugging/tree/MkfsOnBootLockup

Is this a bug I should submit as an issue or have I done something really silly?

[Laczen]

Hi @nakato, could it be that it just takes a long time ? When the automount is used on a littlefs system it will first try to mount it and only if it fails a format will be performed. It can take littlefs a long time to figure out that there is really no lfs filestem on the flash area, especially if the area is large.

[nakato]

If I run fs mount littlefs /lfs without a FS on the storage, it detects there isn't a filesystem and performs the formatting and mounts it in less than 3 seconds, should it be longer than that with automount?

With automount configured, the console over USB CDC never comes up, the device never shows up in lsusb, and there is no change even over 10 minutes. If I remove automount, there still isn't a littlefs filesystem in place after that wait.

For the RP2040, the size is DT_SIZE_M(1).

For the Nice!Nano (NRF52840) device it is substantially smaller at 0x8000 (32K).

Both exhibit identical behaviour.

[Laczen]

In that case, there is indeed something going wrong. You could add some logging in the littlefs_init() routine at the bottom of littlefs_fs.c to see why the call to mount fails.

[nakato]

It's very difficult to get logging out of this, as the lockup breaks log output.

When I set CONFIG_LOG_MODE_IMMEDIATE=y, I get less output than leaving that at the default ``CONFIG_LOG_MODE_DEFERRED`.

With the example code, which only has a app/prj.conf and a device tree to setup storage-partition and fstab, with app/src/main.c only containing an empty sample boilerplate the second boot does mount littlefs after hard-resetting actually. I think I was confusing the lockup on every boot with the version that has some code, which is using settings and using settings_save() in my app's main function, and the lockup there repeats every time.

[nakato]

I've managed to attach a debugger to the RP2040 based device.

Thread 1 "rp2040.core0" received signal SIGINT, Interrupt.
arch_system_halt (reason=reason@entry=0) at /home/nakato/zephyrproject/zephyr/kernel/fatal.c:30
30              for (;;) {
(gdb) bt
#0  arch_system_halt (reason=reason@entry=0) at /home/nakato/zephyrproject/zephyr/kernel/fatal.c:30
#1  0x1000ee0e in k_sys_fatal_error_handler (reason=reason@entry=0, esf=esf@entry=0x2000c960 <z_interrupt_stacks+1984>)
    at /home/nakato/zephyrproject/zephyr/kernel/fatal.c:44
#2  0x1000eec8 in z_fatal_error (reason=0, reason@entry=268465281, esf=esf@entry=0x2000c960 <z_interrupt_stacks+1984>)
    at /home/nakato/zephyrproject/zephyr/kernel/fatal.c:119
#3  0x10007338 in z_arm_fatal_error (reason=268465281, reason@entry=0, esf=0x2000c960 <z_interrupt_stacks+1984>, 
    esf@entry=0x2000c980 <z_interrupt_stacks+2016>) at /home/nakato/zephyrproject/zephyr/arch/arm/core/fatal.c:86
#4  0x10007480 in z_arm_fault (msp=<optimized out>, psp=<optimized out>, exc_return=<optimized out>, callee_regs=<optimized out>)
    at /home/nakato/zephyrproject/zephyr/arch/arm/core/cortex_m/fault.c:1157
#5  0x10007554 in z_arm_hard_fault () at /home/nakato/zephyrproject/zephyr/arch/arm/core/cortex_m/fault_s.S:102
#6  <signal handler called>
#7  0x00000034 in ?? ()
#8  0x00f01000 in ?? ()

0x00f01000 is an address in the range of the storage-partition. Did it get a pointer mixed up and that caused a hard fault?

[Laczen]

Hi @nakato, it is a bit confusing for me. Could you try and reformulate the problem. As far as I can tell the auto mount fails and then if it is used as a backend for settings the system hangs. I am however not completely sure this is correct. If I am correct there are 2 problems:

1. Auto mount fails on unformatted partition,
2. The settings system hangs when trying to use it on a unmounted filesystem.

[nakato]

This is the entirety of the C code that locks up the system on boot, as can be seen in the minimal reproduction example

#include <zephyr/logging/log.h>
LOG_MODULE_REGISTER(main, CONFIG_APP_LOG_LEVEL);
#include <zephyr/kernel.h>
#include <app_version.h>
#define DELAY_TIME K_MSEC(100)
int main(void)
{
	LOG_INF("App:\n  - Version: %s", APP_VERSION_STRING);
	while (1) {
		k_sleep(DELAY_TIME);
	}
	return 0;
}

1. Auto mount fails on unformatted partition,

No, it doesn't just fail to mount the filesystem, it locks up the whole system. I can't get logs out of it to do print-based-debugging.

If I set CONFIG_BOOT_DELAY=5000 and CONFIG_LOG_MODE_IMMEDIATE=y, I get no logs at all before it locks up.
If I set CONFIG_BOOT_DELAY=5000 and CONFIG_LOG_MODE_DEFERRED=y, I get less than a line of a log message before it crashes, how much of a line is variable.
If I do not set CONFIG_BOOT_DELAY, the MCU locks up before it can even perform the USB handshake.

The stacktrace shows it has landed itself in z_arm_hard_fault somehow.

2. The settings system hangs when trying to use it on a unmounted filesystem.

This is after I get littlefs formatted and mounted. Lets just forget I mentioned that for now as that requires code and I have not produced a minimal reproduction example for it. Based on the stack-trace, which comes from the minimal reproduction example on first-boot after wiping the storage-partition, there's no reason for me to mess around with any lockups/crashes in settings yet. I just suspect it may be related because both are on the write path.

Edit: I just noticed the reproduction example was private. That isn't very useful, it's public now.

[nakato]

I suspect this issue is the same as the one reported in #78729

I downgraded zephyrproject-rtos/littlefs to commit 652f2c5, which has resulted in a working littlefs, with no other changes.

I found I could get logs out of the console on boot by inserting a healthy amount of k_sleep(K_MSEC(1000)) into the littlefs format functions, but I have no idea why it's failing. I can put a log message and sleep on line 1991, and it is logged, but a log message and sleep at the very top of the lfs_dir_traverse never shows up, which is called at 1993.

I have no idea how to fix the bug, let alone bisect it beyond being able to say zephyrproject-rtos/littlefs@ca583fd fails and zephyrproject-rtos/littlefs@652f2c5 works. That's not the solution however.

[Laczen]

@nakato, congrats on finding the problem. What I don't understand it that this only appears on automount, or is this no longer valid ? As this is clearly a bug I would report it as such.

[nakato]

I updated littlefs back to ca583fd, and on a guess set CONFIG_MAIN_STACK_SIZE=2048, which is an increase from the default of CONFIG_MAIN_STACK_SIZE=1024, and littlefs automount works!

I think that would make sense why both automount and zephyr/samples/subsys/fs/littlefs/src/main.c failed, but from shell the command fs mount littlefs /lfs worked, as shell's default is CONFIG_SHELL_STACK_SIZE=2048.

I presume this is still worth creating an issue for?

[Laczen]

Hi @nakato, I would close this with a answer to your problem in bold:

HAVING PROBLEMS WITH LITTLEFS, FIRST TRY INCREASING THE STACK SIZE

Thank you for your perseverance.

[nakato]

HAVING PROBLEMS WITH LITTLEFS, FIRST TRY INCREASING THE STACK SIZE