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: Create a script /store/events/sd.mounted/logging: log file log file /sd/ovms.log log level verbose log level info ssh Unplug USB Power up module from 12V supply Any tasks accessing SD CARD will lock-up, sometime during the boot. Accessing other VFS areas seems ok. 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.