That timing issue on headless boot-up, with 3.1 hardware, seems to be a deadlock within Espressif vfs/fat. 

I can repeat the issue by:

  1. Create a script /store/events/sd.mounted/logging:

    log file
    log file /sd/ovms.log
    log level verbose
    log level info ssh

  2. Unplug USB

  3. Power up module from 12V supply

  4. Any tasks accessing SD CARD will lock-up, sometime during the boot. Accessing other VFS areas seems ok.

  5. Can re-connect USB and come in with terminal emulator, ten seconds or more after boot, to examine the stack/etc.

Here is the task status:

OVMS# module tasks stack
Number of Tasks = 16      Stack:  Now   Max Total    Heap 32-bit SPIRAM
3FFAFB48  1 Blk esp_timer         388   548  4096   38080    644  21756
  0x400dc0e3  0x4008ebed
3FFBDD5C  2 Blk eventTask         440  1208  4608       0      0      0
  0x401b3814  0x4008ebed  0x401bcc06
3FFBFB58  3 Blk OVMS Events      1204  3812  6144   77388      0   6608
  0x4008526a  0x4008ebed  0x4015e6b5  0x4008533c  0x401e2e53  0x40096a8c  0x4015eb7d  0x400e585a  0x400e6ece  0x400e4450  0x40085148  0x400eaec3  0x400eb768  0x400e9d1c  0x400ea6ec  0x400ea7f8  0x4008ebed  0x400ea808
3FFC4794  4 Blk OVMS CanRx        432   432  1024       0      0      0
  0x400d39fd  0x4008ebed
3FFC884C  5 Blk ipc0              392   424  1024    7776      0      0
  0x4008240b  0x4008ebed  0x400814fd
3FFC8E4C  6 Blk ipc1              392   504  1024      12      0      0
  0x4008240b  0x4008ebed  0x40081590
3FFCAC74  9 Rdy IDLE              368   496  1024       0      0      0
  0x4008fd60
3FFCB208 10 Rdy IDLE              356   484  1024       0      0      0
  0x4008fd60  0x4008e0b7  0x4008e0b7
3FFCBF9C 11 Blk Tmr Svc           392   872  3072       0      0 168816
  0x40090cdf  0x40090be4
3FFCF9F4 16 Blk tiT               492   700  3072     232      0    148
  0x401fc049  0x4008ebed  0x40091ef6  0x401effe8  0x401f000c  0x401e7562  0x401e7562
3FFD5CA4 17 Blk OVMS SIMCOM      1584  2400  4096     284      0      0
  0x4008526a  0x4008ebed  0x4015e6b5  0x4008533c  0x40000000  0x401e2e53  0x4015eb7d  0x400e585a  0x400e6ece  0x400e4450  0x40085148  0x40216acc  0x402177dc  0x401df626  0x401df4d5  0x401dfa38  0x401dfa8b  0x401e189e  0x401e2e69  0x4015eb7d  0x400e585a  0x400e6ece  0x400e4450  0x40085148  0x401379b5  0x400e58a1  0x40137a1b  0x40137a68
3FFD7C54 18 Blk wifi              432  1824  4096     240      0   1092
  0x4008ab40  0x4008ebed
3FFDA3EC 19 Blk pmT               408   568  2560       0      0      0
  0x401cb6c9  0x4008ebed  0x401cb751
3FFDAA04 20 Blk OVMS Vehicle      452   452  3072       0      0      0
  0x4013ce45  0x4008ebed  0x4021f6e9
3FFDEC24 21 Rdy OVMS Console      760  3048  6144     220  15488  12000
  0x400e6790  0x400f2a3b  0x400f6517  0x400f6585  0x400f2a72  0x400e9830  0x40197436  0x4021f01e  0x400e4508  0x400e986c  0x400e9a68  0x400e43ac  0x400e43bb  0x400f5280
3FFDF604 22 Blk mdns              412   412  4096       0      0      0
  0x4020bae6  0x4008ebed

The interesting tasks are OVMS Events:

$ ~/esp/xtensa-esp32-elf/bin/xtensa-esp32-elf-addr2line -pfiaC -e build/ovms3.elf 0x4008526a  0x4008ebed  0x4015e6b5  0x4008533c  0x401e2e53  0x40096a8c  0x4015eb7d  0x400e585a  0x400e6ece  0x400e4450  0x40085148  0x400eaec3  0x400eb768  0x400e9d1c  0x400ea6ec  0x400ea7f8  0x4008ebed  0x400ea808
0x4008526a: lock_acquire_generic at /Users/mark/esp/esp-idf/components/newlib/./locks.c:157
0x4008ebed: xQueueGenericReceive at /Users/mark/esp/esp-idf/components/freertos/./queue.c:2037
0x4015e6b5: esp_vfs_write at /Users/mark/esp/esp-idf/components/vfs/./vfs.c:540
0x4008533c: _lock_acquire at /Users/mark/esp/esp-idf/components/newlib/./locks.c:165
0x401e2e53: vfs_fat_fsync at /Users/mark/esp/esp-idf/components/fatfs/src/vfs_fat.c:350
0x40096a8c: _fflush_r at /home/jeroen/esp8266/esp32/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/stdio/../../../.././newlib/libc/stdio/fflush.c:282
0x4015eb7d: fsync at /Users/mark/esp/esp-idf/components/vfs/./vfs.c:552 (discriminator 3)
0x400e585a: OvmsCommandApp::LogBuffer(LogBuffers*, char const*, __va_list_tag) at /Users/mark/Documents/ovms/Open-Vehicle-Monitoring-System-3/vehicle/OVMS.V3/main/./ovms_command.cpp:94
0x400e6ece: OvmsCommandApp::Log(char const*, __va_list_tag) at /Users/mark/Documents/ovms/Open-Vehicle-Monitoring-System-3/vehicle/OVMS.V3/main/./ovms_command.cpp:94
0x400e4450: ConsoleAsync::ConsoleLogger(char const*, __va_list_tag) at /Users/mark/Documents/ovms/Open-Vehicle-Monitoring-System-3/vehicle/OVMS.V3/main/./console_async.cpp:118
0x40085148: esp_log_write at /Users/mark/esp/esp-idf/components/log/./log.c:215
0x400eaec3: Housekeeping::Metrics(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, void*) at /Users/mark/Documents/ovms/Open-Vehicle-Monitoring-System-3/vehicle/OVMS.V3/main/./ovms_housekeeping.cpp:221
0x400eb768: std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::_M_data() const at /Users/mark/esp/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/5.2.0/bits/basic_string.h:135
 (inlined by) std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::_M_is_local() const at /Users/mark/esp/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/5.2.0/bits/basic_string.h:170
 (inlined by) std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::_M_dispose() at /Users/mark/esp/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/5.2.0/bits/basic_string.h:179
 (inlined by) std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::~basic_string() at /Users/mark/esp/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/5.2.0/bits/basic_string.h:544
 (inlined by) void std::_Mem_fn_base<void (Housekeeping::*)(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, void*), true>::operator()<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, void*, void>(Housekeeping*, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&&, void*&&) const at /Users/mark/esp/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/5.2.0/functional:600
 (inlined by) void std::_Bind<std::_Mem_fn<void (Housekeeping::*)(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, void*)> (Housekeeping*, std::_Placeholder<1>, std::_Placeholder<2>)>::__call<void, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&&, void*&&, 0u, 1u, 2u>(std::tuple<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&&, void*&&>&&, std::_Index_tuple<0u, 1u, 2u>) at /Users/mark/esp/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/5.2.0/functional:1074
 (inlined by) void std::_Bind<std::_Mem_fn<void (Housekeeping::*)(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, void*)> (Housekeeping*, std::_Placeholder<1>, std::_Placeholder<2>)>::operator()<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, void*, void>(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&&, void*&&) at /Users/mark/esp/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/5.2.0/functional:1133
 (inlined by) std::_Function_handler<void (std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, void*), std::_Bind<std::_Mem_fn<void (Housekeeping::*)(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, void*)> (Housekeeping*, std::_Placeholder<1>, std::_Placeholder<2>)> >::_M_invoke(std::_Any_data const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&&, void*&&) at /Users/mark/esp/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/5.2.0/functional:1871
0x400e9d1c: std::function<void (std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, void*)>::operator()(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, void*) const at /Users/mark/esp/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/5.2.0/functional:2271
0x400ea6ec: std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::_M_data() const at /Users/mark/esp/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/5.2.0/bits/basic_string.h:135
 (inlined by) std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::_M_is_local() const at /Users/mark/esp/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/5.2.0/bits/basic_string.h:170
 (inlined by) std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::_M_dispose() at /Users/mark/esp/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/5.2.0/bits/basic_string.h:179
 (inlined by) std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::~basic_string() at /Users/mark/esp/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/5.2.0/bits/basic_string.h:544
 (inlined by) OvmsEvents::HandleQueueSignalEvent(event_queue_t*) at /Users/mark/Documents/ovms/Open-Vehicle-Monitoring-System-3/vehicle/OVMS.V3/main/./ovms_events.cpp:152
0x400ea7f8: OvmsEvents::EventTask() at /Users/mark/Documents/ovms/Open-Vehicle-Monitoring-System-3/vehicle/OVMS.V3/main/./ovms_events.cpp:126
0x4008ebed: xQueueGenericReceive at /Users/mark/esp/esp-idf/components/freertos/./queue.c:2037
0x400ea808: std::_Rb_tree<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::__cxx11::list<EventCallbackEntry*, std::allocator<EventCallbackEntry*> >*>, std::_Select1st<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::__cxx11::list<EventCallbackEntry*, std::allocator<EventCallbackEntry*> >*> >, std::less<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::__cxx11::list<EventCallbackEntry*, std::allocator<EventCallbackEntry*> >*> > >::_M_get_insert_unique_pos(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) at /Users/mark/esp/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/5.2.0/bits/stl_tree.h:1800

And OVMS SIMCOM:

$ ~/esp/xtensa-esp32-elf/bin/xtensa-esp32-elf-addr2line -pfiaC -e build/ovms3.elf 0x4008526a  0x4008ebed  0x4015e6b5  0x4008533c  0x40000000  0x401e2e53  0x4015eb7d  0x400e585a  0x400e6ece  0x400e4450  0x40085148  0x40216acc  0x402177dc  0x401df626  0x401df4d5  0x401dfa38  0x401dfa8b  0x401e189e  0x401e2e69  0x4015eb7d  0x400e585a  0x400e6ece  0x400e4450  0x40085148  0x401379b5  0x400e58a1  0x40137a1b  0x40137a68
0x4008526a: lock_acquire_generic at /Users/mark/esp/esp-idf/components/newlib/./locks.c:157
0x4008ebed: xQueueGenericReceive at /Users/mark/esp/esp-idf/components/freertos/./queue.c:2037
0x4015e6b5: esp_vfs_write at /Users/mark/esp/esp-idf/components/vfs/./vfs.c:540
0x4008533c: _lock_acquire at /Users/mark/esp/esp-idf/components/newlib/./locks.c:165
0x40000000: ?? ??:0
0x401e2e53: vfs_fat_fsync at /Users/mark/esp/esp-idf/components/fatfs/src/vfs_fat.c:350
0x4015eb7d: fsync at /Users/mark/esp/esp-idf/components/vfs/./vfs.c:552 (discriminator 3)
0x400e585a: OvmsCommandApp::LogBuffer(LogBuffers*, char const*, __va_list_tag) at /Users/mark/Documents/ovms/Open-Vehicle-Monitoring-System-3/vehicle/OVMS.V3/main/./ovms_command.cpp:94
0x400e6ece: OvmsCommandApp::Log(char const*, __va_list_tag) at /Users/mark/Documents/ovms/Open-Vehicle-Monitoring-System-3/vehicle/OVMS.V3/main/./ovms_command.cpp:94
0x400e4450: ConsoleAsync::ConsoleLogger(char const*, __va_list_tag) at /Users/mark/Documents/ovms/Open-Vehicle-Monitoring-System-3/vehicle/OVMS.V3/main/./console_async.cpp:118
0x40085148: esp_log_write at /Users/mark/esp/esp-idf/components/log/./log.c:215
0x40216acc: sdmmc_write_sectors_dma at /Users/mark/esp/esp-idf/components/sdmmc/./sdmmc_cmd.c:361 (discriminator 4)
0x402177dc: sdmmc_write_sectors at /Users/mark/esp/esp-idf/components/sdmmc/./sdmmc_cmd.c:750
0x401df626: ff_sdmmc_write at /Users/mark/esp/esp-idf/components/fatfs/src/diskio_sdmmc.c:51
0x401df4d5: ff_disk_write at /Users/mark/esp/esp-idf/components/fatfs/src/diskio.c:74
0x401dfa38: sync_window at /Users/mark/esp/esp-idf/components/fatfs/src/ff.c:4730
0x401dfa8b: move_window at /Users/mark/esp/esp-idf/components/fatfs/src/ff.c:4730
0x401e189e: f_sync at /Users/mark/esp/esp-idf/components/fatfs/src/ff.c:4730
0x401e2e69: vfs_fat_fsync at /Users/mark/esp/esp-idf/components/fatfs/src/vfs_fat.c:351
0x4015eb7d: fsync at /Users/mark/esp/esp-idf/components/vfs/./vfs.c:552 (discriminator 3)
0x400e585a: OvmsCommandApp::LogBuffer(LogBuffers*, char const*, __va_list_tag) at /Users/mark/Documents/ovms/Open-Vehicle-Monitoring-System-3/vehicle/OVMS.V3/main/./ovms_command.cpp:94
0x400e6ece: OvmsCommandApp::Log(char const*, __va_list_tag) at /Users/mark/Documents/ovms/Open-Vehicle-Monitoring-System-3/vehicle/OVMS.V3/main/./ovms_command.cpp:94
0x400e4450: ConsoleAsync::ConsoleLogger(char const*, __va_list_tag) at /Users/mark/Documents/ovms/Open-Vehicle-Monitoring-System-3/vehicle/OVMS.V3/main/./console_async.cpp:118
0x40085148: esp_log_write at /Users/mark/esp/esp-idf/components/log/./log.c:215
0x401379b5: simcom::Task() at /Users/mark/Documents/ovms/Open-Vehicle-Monitoring-System-3/vehicle/OVMS.V3/components/simcom/src/simcom.cpp:88
0x400e58a1: OvmsCommandApp::HexDump(char const*, char const*, char const*, unsigned int, unsigned int) at /Users/mark/Documents/ovms/Open-Vehicle-Monitoring-System-3/vehicle/OVMS.V3/main/./ovms_command.cpp:94
0x40137a1b: simcom::Task() at /Users/mark/Documents/ovms/Open-Vehicle-Monitoring-System-3/vehicle/OVMS.V3/components/simcom/src/simcom.cpp:105
0x40137a68: simcom::State1Ticker1() at /Users/mark/Documents/ovms/Open-Vehicle-Monitoring-System-3/vehicle/OVMS.V3/components/simcom/src/simcom.cpp:523

The other tasks all look ok.

From what I can see, the task producing the log entry is dong a fsync, which presumably locks fat then locks vfs. Then another task tries to do a log as well, and gets locked up.

If I comment-out the fsync in OvmsCommandApp::LogBuffer of ovms_command.cpp (line 614), it seems to avoid the problem.

I’ve partially worked around the problem by introducing a mutex lock in ovms_command.cpp, when writing to the log file. That avoids the issue in ESP IDF. I’ve also raised it to Espressif.

* b38b0ef (HEAD -> master, origin/master, origin/HEAD)
Mutex protect fsync function call, on logging, to workaround ESP IDF bug
https://github.com/espressif/esp-idf/issues/1837

It is an ugly solution, and doesn’t seem 100% effective. I’m really not sure what is going on. Any ideas?

Regards, Mark.