Run fs.readFileSync before fs.statSync will cause ESP32 exception. #1163

wilberforce · 2017-05-09T11:17:19Z

Reported here...
http://forum.espruino.com/conversations/304604/#comment13624116


Run fs.readFileSync before fs.statSync will cause ESP32 exception.
example:
var fs=require("fs");
fs.writeFileSync("temp.txt", "hello 123");
fs.readFileSync("temp.txt");
fs.statSync("temp.txt");

espruino version 1v92
console output:

fs.statSync("temp.txt")
Guru Meditation Error of type StoreProhibited occurred on core 0. Exception was unhandled.
Register dump:
PC : 0x401145cf PS : 0x00060430 A0 : 0x801158e6 A1 : 0x3ffd2840
A2 : 0x00000001 A3 : 0x00000000 A4 : 0x00000001 A5 : 0x0000ffff
A6 : 0x3ffd2948 A7 : 0x00000038 A8 : 0x0000ffff A9 : 0x0000000a
A10 : 0x00000013 A11 : 0x3ffd2991 A12 : 0x3ffcb950 A13 : 0x00000019
A14 : 0x000000ff A15 : 0x3ffd2890 SAR : 0x00000010 EXCCAUSE: 0x0000001d
EXCVADDR: 0x00000001 LBEG : 0x4000c46c LEND : 0x4000c477 LCOUNT : 0x00000000
Backtrace: 0x401145cf:0x3ffd2840 0x401158e6:0x3ffd2860 0x40133332:0x3ffd2940 0x40105df6:0x3ffd29f0 0x40108728:0x3ffd2a70 0x40106f0e:0x3ffd2bb0 0x40106fbc:0x3ffd2be0 0x40107083:0x3ffd2c00 0x40107332:0x3ffd2c20 0x40107346:0x3ffd2c40 0x40107356:0x3ffd2c60 0x40107c87:0x3ffd2c80 0x401081f3:0x3ffd2ca0 0x40108fb3:0x3ffd2cc0 0x401095c6:0x3ffd2ce0 0x4010bd3c:0x3ffd2d00 0x4010e4b5:0x3ffd2de0 0x4010e9b9:0x3ffd2e10 0x4010ea27:0x3ffd2e40 0x4010ea80:0x3ffd2e60 0x4010f2b1:0x3ffd2ed0 0x4012a817:0x3ffd2ef0
================= CORE DUMP START =================

Will need to get core dump and elf file and find actual crash point.

Wondering if the write is closed properly?

The text was updated successfully, but these errors were encountered:

gfwilliams · 2017-05-09T11:22:02Z

How hard is it to build the Flash filesystem code for Linux now? It could be a good way to try and track this down?

wilberforce · 2017-05-09T11:45:12Z

@gfwilliams

I think the issue is here....

https://github.com/espruino/Espruino/blob/master/libs/filesystem/jswrap_file.c#L423

http://elm-chan.org/fsw/ff/doc/sync.html

f_sync keeps the file open, so it can be appended too, and I think we want a proper close.

How hard is it to build the Flash filesystem code for Linux now

The issue is the code is littered with #ifdef Linux etc, so perhaps a switch to use the fats. It would be cleaner to remove the direct file code, but then the Linux build would not be able to work with real files.

wilberforce · 2017-05-09T12:12:08Z

Should there be a close_dir for the fatfs here too?

https://github.com/espruino/Espruino/blob/master/libs/filesystem/jswrap_fs.c#L139

gfwilliams · 2017-05-09T12:44:16Z

I think f_sync is correct. You're looking at file.write, not writeFile. It's meant to leave the file structure open but to keep the SD card properly up to date.

The lack of close_dir definitely looks like a bug, but I'm not sure it'd have caused this crash?

And yeah, we definitely want the original file access stuff in there - Espruino does seem to be used on OpenWRT/Linux.

wilberforce · 2017-05-10T06:37:47Z

documenting here so can used in the future:

cut and paste from the IDE:

cat > coredump.dat - just the stuff between:
================= CORE DUMP START =================
and
================= CORE DUMP END =================
and paste and then hit ctrl-d

esp-idf/components/espcoredump/espcoredump.py info_corefile -t b64 -c coredump.dat espruino_1v92.53_esp32.elf

The elf file needs to match the binary - so this would need to be from a build.

in this case is crashing here:

pc             0x40116b57       0x40116b57 <get_fileinfo+159>


#0  0x40116b57 in get_fileinfo ()
#1  0x40117e6e in f_readdir ()
#2  0x40135b62 in jswrap_fs_readFile ()

full output as a sample:

espcoredump.py v0.1-dev
===============================================================
==================== ESP32 CORE DUMP START ====================

================== CURRENT THREAD REGISTERS ===================
pc             0x40116b57       0x40116b57 <get_fileinfo+159>
lbeg           0x4000c46c       1073792108
lend           0x4000c477       1073792119
lcount         0x0      0
sar            0x10     16
ps             0x60720  395040
threadptr      <unavailable>
br             <unavailable>
scompare1      <unavailable>
acclo          <unavailable>
acchi          <unavailable>
m0             <unavailable>
m1             <unavailable>
m2             <unavailable>
m3             <unavailable>
expstate       <unavailable>
f64r_lo        <unavailable>
f64r_hi        <unavailable>
f64s           <unavailable>
fcr            <unavailable>
fsr            <unavailable>
a0             0x40117e6e       1074888302
a1             0x3ffd2560       1073554784
a2             0xa5a5a5a5       -1515870811
a3             0x0      0
a4             0xa5a5a5a5       -1515870811
a5             0xffff   65535
a6             0x3ffd2668       1073555048
a7             0x0      0
a8             0xffff   65535
a9             0xa      10
a10            0x13     19
a11            0x3ffd26b1       1073555121
a12            0x3ffcb968       1073527144
a13            0x19     25
a14            0xff     255
a15            0x3ffd25b0       1073554864

==================== CURRENT THREAD STACK =====================
#0  0x40116b57 in get_fileinfo ()
#1  0x40117e6e in f_readdir ()
#2  0x40135b62 in jswrap_fs_readFile ()
#3  0x401079aa in jsnCallFunction ()
#4  0x4010ca04 in jspeFunctionCall ()
#5  0x40108ca8 in jspeFactorFunctionCall ()
#6  0x40108d58 in jspeFactorFunctionCall ()
#7  0x40108e33 in jspeUnaryExpression ()
#8  0x401090fa in __jspeBinaryExpression ()
#9  0x4010910e in __jspeBinaryExpression ()
#10 0x4010911e in __jspeBinaryExpression ()
#11 0x4010c942 in jspeFunctionCall ()
#12 0x40108ca8 in jspeFactorFunctionCall ()
#13 0x40108d58 in jspeFactorFunctionCall ()
#14 0x40108e33 in jspeUnaryExpression ()
#15 0x401090fa in __jspeBinaryExpression ()
#16 0x4010910e in __jspeBinaryExpression ()
#17 0x4010911e in __jspeBinaryExpression ()
#18 0x40109b33 in __jspeAssignmentExpression ()
#19 0x4010c49b in jspeStatement ()
#20 0x4010d2cb in jspeStatementTry ()
#21 0x4010d932 in jspeStatementFor ()
#22 0x4010df48 in jspeFactorDelete ()
#23 0x4011079d in jsiHandleNewLine ()
#24 0x40110ca1 in jsiHandleChar ()
#25 0x40110d0f in jsiHandleChar ()
#26 0x40110d68 in jsiHandleIOEventForConsole ()
#27 0x401115bd in jsiIdle ()
#28 0x4012ce7f in esp32_neopixelWrite ()

======================== THREADS INFO =========================
  Id   Target Id         Frame
  11   process 10        0x40084b73 in xQueueGenericReceive (xQueue=0x0, pvBuffer=<optimized out>, xTicksToWait=<unavailable>, xJustPeeking=0) at /mnt/c/Users/rhys/esp32/EspruinoBuildTools/esp32/build/esp-idf/components/freertos/./queue.c:1538
  10   process 9         0x40084b73 in xQueueGenericReceive (xQueue=0x3ffb6108, pvBuffer=<optimized out>, xTicksToWait=<unavailable>, xJustPeeking=0) at /mnt/c/Users/rhys/esp32/EspruinoBuildTools/esp32/build/esp-idf/components/freertos/./queue.c:1538
  9    process 8         0x40084b73 in xQueueGenericReceive (xQueue=0x3ffb6d40 <SigInMacISR+348>, pvBuffer=<optimized out>, xTicksToWait=<unavailable>, xJustPeeking=0) at /mnt/c/Users/rhys/esp32/EspruinoBuildTools/esp32/build/esp-idf/components/freertos/./queue.c:1538
  8    process 7         0x40084b73 in xQueueGenericReceive (xQueue=0x0, pvBuffer=<optimized out>, xTicksToWait=<unavailable>, xJustPeeking=0) at /mnt/c/Users/rhys/esp32/EspruinoBuildTools/esp32/build/esp-idf/components/freertos/./queue.c:1538
  7    process 6         0x40084b73 in xQueueGenericReceive (xQueue=0x3ffb2f70, pvBuffer=<optimized out>, xTicksToWait=<unavailable>, xJustPeeking=0) at /mnt/c/Users/rhys/esp32/EspruinoBuildTools/esp32/build/esp-idf/components/freertos/./queue.c:1538
  6    process 5         0x40085f90 in pvTaskIncrementMutexHeldCount () at /mnt/c/Users/rhys/esp32/EspruinoBuildTools/esp32/build/esp-idf/components/freertos/./tasks.c:4426
  5    process 4         0x40086436 in prvProcessExpiredTimer (xNextExpireTime=0, xTimeNow=0) at /mnt/c/Users/rhys/esp32/EspruinoBuildTools/esp32/build/esp-idf/components/freertos/./timers.c:389
  4    process 3         0x40084b73 in xQueueGenericReceive (xQueue=0x3ffb5100 <arp_table+168>, pvBuffer=<optimized out>, xTicksToWait=2148485547, xJustPeeking=0) at /mnt/c/Users/rhys/esp32/EspruinoBuildTools/esp32/build/esp-idf/components/freertos/./queue.c:1538
  3    process 2         0x40084b73 in xQueueGenericReceive (xQueue=0x3ffcdbf4, pvBuffer=<optimized out>, xTicksToWait=1073599200, xJustPeeking=0) at /mnt/c/Users/rhys/esp32/EspruinoBuildTools/esp32/build/esp-idf/components/freertos/./queue.c:1538
  2    process 1         0x4014fb14 in esp_event_loop_task (pvParameters=0x8) at /mnt/c/Users/rhys/esp32/EspruinoBuildTools/esp32/build/esp-idf/components/esp32/./event_loop.c:55
* 1    <main task>       0x40116b57 in get_fileinfo ()

======================= ALL MEMORY REGIONS ========================
Name   Address   Size   Attrs
.rtc.text 0x400c0000 0x0 RW
.iram0.vectors 0x40080000 0x400 R XA
.iram0.text 0x40080400 0x1c604 R XA
.dram0.data 0x3ffb0000 0x1f94 RW A
.flash.rodata 0x3f400010 0x1a4f4 RW A
.flash.text 0x400d0018 0x8a680 R XA
.coredump.tasks 0x3ffd2eb8 0x174 RW
.coredump.tasks 0x3ffd24a0 0xa0c RW
.coredump.tasks 0x3ffcea34 0x174 RW
.coredump.tasks 0x3ffce8c0 0x168 RW
.coredump.tasks 0x3ffdd3d8 0x174 RW
.coredump.tasks 0x3ffdd220 0x1ac RW
.coredump.tasks 0x3ffd05ec 0x174 RW
.coredump.tasks 0x3ffd04a0 0x140 RW
.coredump.tasks 0x3ffcf4ac 0x174 RW
.coredump.tasks 0x3ffcf3c0 0xe0 RW
.coredump.tasks 0x3ffde91c 0x174 RW
.coredump.tasks 0x3ffde830 0xe0 RW
.coredump.tasks 0x3ffda93c 0x174 RW
.coredump.tasks 0x3ffda840 0xf0 RW
.coredump.tasks 0x3ffd3e90 0x174 RW
.coredump.tasks 0x3ffd3d70 0x114 RW
.coredump.tasks 0x3ffd5580 0x174 RW
.coredump.tasks 0x3ffd5470 0x104 RW
.coredump.tasks 0x3ffdb9e4 0x174 RW
.coredump.tasks 0x3ffdb8e0 0xf8 RW
.coredump.tasks 0x3ffcd1ec 0x174 RW
.coredump.tasks 0x3ffcd100 0xe0 RW

===================== ESP32 CORE DUMP END =====================
===============================================================

wilberforce · 2017-05-10T21:45:10Z

https://www.esp32.com/viewtopic.php?t=263 How to trace crash point

wilberforce · 2017-05-11T10:04:39Z

make clean
source scripts/provision.sh ESP32
BOARD=ESP32 DEBUG=1 make
cp espruino_1v92.53_esp32.bin espruino_esp32.bin
# flash firmware and run:

var fs=require("fs");
fs.writeFileSync("temp.txt", "hello 123");
console.log(fs.statSync("temp.txt"));

copy content between:

================= CORE DUMP START =================
================= CORE DUMP END =================

cat > coredump.dat
esp-idf/components/espcoredump/espcoredump.py info_corefile -t b64 -c coredump.dat espruino_1v92.53_esp32.elf
esp-idf/components/espcoredump/espcoredump.py dbg_corefile -t b64 -c coredump.dat espruino_1v92.53_esp32.elf

#0  0x40116993 in get_fileinfo (dp=<optimized out>, fno=<optimized out>) at libs/filesystem/fat_sd/ff.c:1811
1811                    p[i] = 0;       /* Terminate LFN string by a \0 */
[Current thread is 1 (<main task>)]

Crash is here terminating the string!
https://github.com/espruino/Espruino/blob/master/libs/filesystem/fat_sd/ff.c#L1811

gfwilliams · 2017-05-11T10:19:35Z

Looks like f_stat expects some of the fields in FILINFO to be populated with pointers or 0, but it's used uninitialised.

I bet a memset(&info, 0, sizeof(info)) in jswrap_fs_stat before the call would fix it?

…, fs.statSync (#1163)

wilberforce · 2017-05-11T10:31:45Z

@gfwilliams
The buffer needed be initialised for long filenames - like it was for readdir

…, fs.statSync (#1163)

wilberforce added the ESP32 This is only a problem on ESP32-based devices label May 9, 2017

wilberforce added a commit that referenced this issue May 11, 2017

Fat FS: closedir after readdir, FS errors should be catchable (#1164)…

7ad4969

…, fs.statSync (#1163)

gfwilliams pushed a commit that referenced this issue May 11, 2017

Fat FS: closedir after readdir, FS errors should be catchable (#1164)…

6fc95d1

…, fs.statSync (#1163)

wilberforce closed this as completed May 13, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Run fs.readFileSync before fs.statSync will cause ESP32 exception. #1163

Run fs.readFileSync before fs.statSync will cause ESP32 exception. #1163

wilberforce commented May 9, 2017 •

edited

gfwilliams commented May 9, 2017

wilberforce commented May 9, 2017 •

edited

wilberforce commented May 9, 2017 •

edited

gfwilliams commented May 9, 2017

wilberforce commented May 10, 2017 •

edited

wilberforce commented May 10, 2017

wilberforce commented May 11, 2017

gfwilliams commented May 11, 2017 •

edited

wilberforce commented May 11, 2017

Run fs.readFileSync before fs.statSync will cause ESP32 exception. #1163

Run fs.readFileSync before fs.statSync will cause ESP32 exception. #1163

Comments

wilberforce commented May 9, 2017 • edited

gfwilliams commented May 9, 2017

wilberforce commented May 9, 2017 • edited

wilberforce commented May 9, 2017 • edited

gfwilliams commented May 9, 2017

wilberforce commented May 10, 2017 • edited

wilberforce commented May 10, 2017

wilberforce commented May 11, 2017

gfwilliams commented May 11, 2017 • edited

wilberforce commented May 11, 2017

wilberforce commented May 9, 2017 •

edited

wilberforce commented May 9, 2017 •

edited

wilberforce commented May 9, 2017 •

edited

wilberforce commented May 10, 2017 •

edited

gfwilliams commented May 11, 2017 •

edited