Periodic FATFS corruption

[simonjo]

Hello,

I have an application that collects power metering info from 2 sources, the first is a pulse counter (using PCNT) and the second is a PZEM004T device that is handled via UART2.

The pulse counter uses an ISR to count the pulses from an S0 pulsemeter, a foreground task reports this counter every minute to a file called pwrmtr-3.log. No problem there.

The PZEM004T is read out every minute by sending a request via UART2, the PZEM004T response triggers an ISR for each byte received, the ISR is a state machine that collects bytes into a complete pakket and then posts it on a queue. The queue is read in above mentioned foreground task that reports the data to the same file pwrmtr-3.log. This also works fine.

This pwrmtr-3.log is part of 4 rotating files with a max size of 128Kb each, if pwrmtr-3.log is full then pwrmtr-0.log is deleted and pwrmtr-1.log is renamed to pwrmtr-0.log... and finally pwrmtr-3.log is renamed to pwrmtr-2.log. These files reside on a FAT partition of 1984Kb mounted with WL.

const esp_vfs_fat_mount_config_t mount_config = {
.format_if_mount_failed = true,
.max_files = 4,
.allocation_unit_size = CONFIG_WL_SECTOR_SIZE
};

int32_t err = esp_vfs_fat_spiflash_mount("/spiflash", "private", &mount_config, &m_vfsWlHandle);

These logfiles are reported by the HTTP server of my application, just open each file, read every entry and report it, then close the file (x4). There is no chance that HTTP server and the part collecting the data run together as these run in the same worker thread and as such will be active in turn but never together, thus we can use a lockless design.

But after a while pwrmtr-3.log seems to be disappeared/corrupted and is recreated empty, I am talking about 3-5 hours for this to happen. After that I see a second file that has unreadable characters in it's name.

The problem must be related to the use of the UART, when I disable the part that handles the PZEM004T (and no ISR for the UART) then there is no file corruption. But the same UART code is working fine in another project that also logs events into a file and allows reporting it via HTTP server.

Below is a logging detail of the moment it goes wrong, pwrmtr-3.log is fine upto 21:24:09 where it writes both the data of the PCNT (src,0) and the PZEM (src,1). But then at 21:25:10 opening of pwrmtr-3.log fails due to some reason and my application re-creates it. The only diff with previous writes seem to be the WL stepping in to do something.

>>>
2021-05-23,21:23:08,D,PWRM,<src,0,active,0.18,15mp,0.211,total,2.106
V (7455362) vfs_fat: vfs_fat_open: path="/pwrmtr-3.log", flags=2, mode=1b6
V (7455362) ff_diskio_spiflash: ff_wl_read - pdrv=0, sector=1, count=1

D (7455372) wl_flash: read - src_addr= 0x00001000, size= 0x00001000
V (7455372) wl_flash: calcAddr - addr= 0x00001000 -> result= 0x001db000, dummy_addr= 0x000ec000
V (7455382) ff_diskio_spiflash: ff_wl_read - pdrv=0, sector=15, count=1

D (7455392) wl_flash: read - src_addr= 0x0000f000, size= 0x00001000
V (7455392) wl_flash: calcAddr - addr= 0x0000f000 -> result= 0x001e9000, dummy_addr= 0x000ec000
V (7455402) ff_diskio_spiflash: ff_wl_write - pdrv=0, sector=15, count=1

D (7455412) wl_flash: erase_range - start_address= 0x0000f000, size= 0x00001000
D (7455422) wl_flash: erase_sector - sector= 0x0000000f
V (7455422) wl_flash: calcAddr - addr= 0x0000f000 -> result= 0x001e9000, dummy_addr= 0x000ec000
V (7455472) wl_partition: erase_range - start_address=0x001e9000, size=0x00001000, result=0x00000000
V (7455472) wl_flash: erase_range - result= 0x00000000
D (7455472) wl_flash: write - dest_addr= 0x0000f000, size= 0x00001000
V (7455472) wl_flash: calcAddr - addr= 0x0000f000 -> result= 0x001e9000, dummy_addr= 0x000ec000
V (7455492) ff_diskio_spiflash: ff_wl_read - pdrv=0, sector=2, count=1

D (7455492) wl_flash: read - src_addr= 0x00002000, size= 0x00001000
V (7455502) wl_flash: calcAddr - addr= 0x00002000 -> result= 0x001dc000, dummy_addr= 0x000ec000
V (7455512) ff_diskio_spiflash: ff_wl_write - pdrv=0, sector=2, count=1

D (7455512) wl_flash: erase_range - start_address= 0x00002000, size= 0x00001000
D (7455522) wl_flash: erase_sector - sector= 0x00000002
V (7455532) wl_flash: calcAddr - addr= 0x00002000 -> result= 0x001dc000, dummy_addr= 0x000ec000
V (7455572) wl_partition: erase_range - start_address=0x001dc000, size=0x00001000, result=0x00000000
V (7455572) wl_flash: erase_range - result= 0x00000000
D (7455572) wl_flash: write - dest_addr= 0x00002000, size= 0x00001000
V (7455582) wl_flash: calcAddr - addr= 0x00002000 -> result= 0x001dc000, dummy_addr= 0x000ec000
V (7455592) ff_diskio_spiflash: ff_wl_ioctl: cmd=0

2021-05-23,21:23:09,D,PWRM,<src,1,active,0.36,15mp,0.473,total,3.998,voltage,230.6,current,0.0,freq,50.0,pf,0.00
V (7455662) vfs_fat: vfs_fat_open: path="/pwrmtr-3.log", flags=2, mode=1b6
V (7455662) ff_diskio_spiflash: ff_wl_read - pdrv=0, sector=1, count=1

D (7455672) wl_flash: read - src_addr= 0x00001000, size= 0x00001000
V (7455682) wl_flash: calcAddr - addr= 0x00001000 -> result= 0x001db000, dummy_addr= 0x000ec000
V (7455692) ff_diskio_spiflash: ff_wl_read - pdrv=0, sector=15, count=1

D (7455692) wl_flash: read - src_addr= 0x0000f000, size= 0x00001000
V (7455702) wl_flash: calcAddr - addr= 0x0000f000 -> result= 0x001e9000, dummy_addr= 0x000ec000
V (7455712) ff_diskio_spiflash: ff_wl_write - pdrv=0, sector=15, count=1

D (7455712) wl_flash: erase_range - start_address= 0x0000f000, size= 0x00001000
D (7455722) wl_flash: erase_sector - sector= 0x0000000f
V (7455732) wl_flash: calcAddr - addr= 0x0000f000 -> result= 0x001e9000, dummy_addr= 0x000ec000
V (7455772) wl_partition: erase_range - start_address=0x001e9000, size=0x00001000, result=0x00000000
V (7455772) wl_flash: erase_range - result= 0x00000000
D (7455772) wl_flash: write - dest_addr= 0x0000f000, size= 0x00001000
V (7455772) wl_flash: calcAddr - addr= 0x0000f000 -> result= 0x001e9000, dummy_addr= 0x000ec000
V (7455792) ff_diskio_spiflash: ff_wl_read - pdrv=0, sector=2, count=1

D (7455792) wl_flash: read - src_addr= 0x00002000, size= 0x00001000
V (7455802) wl_flash: calcAddr - addr= 0x00002000 -> result= 0x001dc000, dummy_addr= 0x000ec000
V (7455812) ff_diskio_spiflash: ff_wl_write - pdrv=0, sector=2, count=1

D (7455812) wl_flash: erase_range - start_address= 0x00002000, size= 0x00001000
D (7455822) wl_flash: erase_sector - sector= 0x00000002
V (7455832) wl_flash: calcAddr - addr= 0x00002000 -> result= 0x001dc000, dummy_addr= 0x000ec000
V (7455872) wl_partition: erase_range - start_address=0x001dc000, size=0x00001000, result=0x00000000
V (7455872) wl_flash: erase_range - result= 0x00000000
D (7455872) wl_flash: write - dest_addr= 0x00002000, size= 0x00001000
V (7455882) wl_flash: calcAddr - addr= 0x00002000 -> result= 0x001dc000, dummy_addr= 0x000ec000
V (7455892) ff_diskio_spiflash: ff_wl_ioctl: cmd=0



2021-05-23,21:24:09,D,PWRM,<src,0,active,0.9,15mp,0.216,total,2.115
V (7515962) vfs_fat: vfs_fat_open: path="/pwrmtr-3.log", flags=2, mode=1b6
V (7515962) ff_diskio_spiflash: ff_wl_read - pdrv=0, sector=1, count=1

D (7515972) wl_flash: read - src_addr= 0x00001000, size= 0x00001000
V (7515972) wl_flash: calcAddr - addr= 0x00001000 -> result= 0x001db000, dummy_addr= 0x000ec000
V (7515982) ff_diskio_spiflash: ff_wl_read - pdrv=0, sector=15, count=1

D (7515992) wl_flash: read - src_addr= 0x0000f000, size= 0x00001000
V (7516002) wl_flash: calcAddr - addr= 0x0000f000 -> result= 0x001e9000, dummy_addr= 0x000ec000
V (7516012) ff_diskio_spiflash: ff_wl_write - pdrv=0, sector=15, count=1

D (7516012) wl_flash: erase_range - start_address= 0x0000f000, size= 0x00001000
D (7516022) wl_flash: erase_sector - sector= 0x0000000f

V (7516022) wl_flash: calcAddr - addr= 0x0000f000 -> result= 0x001e9000, dummy_addr= 0x000ec000
V (7516072) wl_partition: erase_range - start_address=0x001e9000, size=0x00001000, result=0x00000000
V (7516072) wl_flash: erase_range - result= 0x00000000
D (7516072) wl_flash: write - dest_addr= 0x0000f000, size= 0x00001000
V (7516082) wl_flash: calcAddr - addr= 0x0000f000 -> result= 0x001e9000, dummy_addr= 0x000ec000
V (7516092) ff_diskio_spiflash: ff_wl_read - pdrv=0, sector=2, count=1

D (7516092) wl_flash: read - src_addr= 0x00002000, size= 0x00001000
V (7516102) wl_flash: calcAddr - addr= 0x00002000 -> result= 0x001dc000, dummy_addr= 0x000ec000
V (7516112) ff_diskio_spiflash: ff_wl_write - pdrv=0, sector=2, count=1

D (7516112) wl_flash: erase_range - start_address= 0x00002000, size= 0x00001000
D (7516122) wl_flash: erase_sector - sector= 0x00000002
V (7516132) wl_flash: calcAddr - addr= 0x00002000 -> result= 0x001dc000, dummy_addr= 0x000ec000
V (7516172) wl_partition: erase_range - start_address=0x001dc000, size=0x00001000, result=0x00000000
V (7516172) wl_flash: erase_range - result= 0x00000000
D (7516172) wl_flash: write - dest_addr= 0x00002000, size= 0x00001000
V (7516182) wl_flash: calcAddr - addr= 0x00002000 -> result= 0x001dc000, dummy_addr= 0x000ec000
V (7516192) ff_diskio_spiflash: ff_wl_ioctl: cmd=0


2021-05-23,21:24:09,D,PWRM,<src,1,active,0.46,15mp,0.508,total,4.44,voltage,230.5,current,0.0,freq,50.0,pf,0.00
V (7516262) vfs_fat: vfs_fat_open: path="/pwrmtr-3.log", flags=2, mode=1b6
V (7516272) ff_diskio_spiflash: ff_wl_read - pdrv=0, sector=1, count=1

D (7516272) wl_flash: read - src_addr= 0x00001000, size= 0x00001000
V (7516282) wl_flash: calcAddr - addr= 0x00001000 -> result= 0x001db000, dummy_addr= 0x000ec000
V (7516292) ff_diskio_spiflash: ff_wl_read - pdrv=0, sector=15, count=1

D (7516292) wl_flash: read - src_addr= 0x0000f000, size= 0x00001000
V (7516302) wl_flash: calcAddr - addr= 0x0000f000 -> result= 0x001e9000, dummy_addr= 0x000ec000
V (7516312) ff_diskio_spiflash: ff_wl_write - pdrv=0, sector=15, count=1

D (7516322) wl_flash: erase_range - start_address= 0x0000f000, size= 0x00001000
D (7516322) wl_flash: erase_sector - sector= 0x0000000f

V (7516332) wl_flash: updateWL - access_count= 0x00000000, pos= 0x000000ec
V (7516372) wl_partition: erase_range - start_address=0x000ec000, size=0x00001000, result=0x00000000
V (7516512) wl_partition: erase_range - start_address=0x001eb000, size=0x00002000, result=0x00000000
V (7516602) wl_partition: erase_range - start_address=0x001ed000, size=0x00002000, result=0x00000000
D (7516602) wl_flash: updateWL - move_count= 0x00000012, pos= 0x00000000,
V (7516602) wl_flash: updateWL - result= 0x00000000

V (7516612) wl_flash: calcAddr - addr= 0x0000f000 -> result= 0x001e8000, dummy_addr= 0x00000000
V (7516652) wl_partition: erase_range - start_address=0x001e8000, size=0x00001000, result=0x00000000
V (7516652) wl_flash: erase_range - result= 0x00000000
D (7516652) wl_flash: write - dest_addr= 0x0000f000, size= 0x00001000
V (7516652) wl_flash: calcAddr - addr= 0x0000f000 -> result= 0x001e8000, dummy_addr= 0x00000000
V (7516672) ff_diskio_spiflash: ff_wl_read - pdrv=0, sector=2, count=1

D (7516672) wl_flash: read - src_addr= 0x00002000, size= 0x00001000
V (7516682) wl_flash: calcAddr - addr= 0x00002000 -> result= 0x001db000, dummy_addr= 0x00000000
V (7516692) ff_diskio_spiflash: ff_wl_write - pdrv=0, sector=2, count=1

D (7516692) wl_flash: erase_range - start_address= 0x00002000, size= 0x00001000
D (7516702) wl_flash: erase_sector - sector= 0x00000002
V (7516712) wl_flash: calcAddr - addr= 0x00002000 -> result= 0x001db000, dummy_addr= 0x00000000
V (7516752) wl_partition: erase_range - start_address=0x001db000, size=0x00001000, result=0x00000000
V (7516752) wl_flash: erase_range - result= 0x00000000
D (7516752) wl_flash: write - dest_addr= 0x00002000, size= 0x00001000
V (7516752) wl_flash: calcAddr - addr= 0x00002000 -> result= 0x001db000, dummy_addr= 0x00000000
V (7516772) ff_diskio_spiflash: ff_wl_ioctl: cmd=0


2021-05-23,21:25:10,D,PWRM,<src,0,active,0.16,15mp,0.201,total,2.131
V (7576842) vfs_fat: vfs_fat_open: path="/pwrmtr-3.log", flags=2, mode=1b6
D (7576842) vfs_fat: vfs_fat_open: fresult=4
V (7576842) vfs_fat: vfs_fat_open: path="/pwrmtr-3.log", flags=602, mode=1b6
2021-05-23,21:25:10,I,PWRM,!Created /pwrmtr-3.log
V (7576852) ff_diskio_spiflash: ff_wl_write - pdrv=0, sector=2, count=1

D (7576862) wl_flash: erase_range - start_address= 0x00002000, size= 0x00001000
D (7576872) wl_flash: erase_sector - sector= 0x00000002
V (7576872) wl_flash: calcAddr - addr= 0x00002000 -> result= 0x001db000, dummy_addr= 0x00000000
V (7576922) wl_partition: erase_range - start_address=0x001db000, size=0x00001000, result=0x00000000
V (7576922) wl_flash: erase_range - result= 0x00000000
D (7576922) wl_flash: write - dest_addr= 0x00002000, size= 0x00001000
V (7576922) wl_flash: calcAddr - addr= 0x00002000 -> result= 0x001db000, dummy_addr= 0x00000000
V (7576942) ff_diskio_spiflash: ff_wl_read - pdrv=0, sector=1, count=1

D (7576942) wl_flash: read - src_addr= 0x00001000, size= 0x00001000
V (7576952) wl_flash: calcAddr - addr= 0x00001000 -> result= 0x001da000, dummy_addr= 0x00000000
V (7576962) ff_diskio_spiflash: ff_wl_write - pdrv=0, sector=19, count=1

D (7576962) wl_flash: erase_range - start_address= 0x00013000, size= 0x00001000
D (7576972) wl_flash: erase_sector - sector= 0x00000013
V (7576982) wl_flash: calcAddr - addr= 0x00013000 -> result= 0x00002000, dummy_addr= 0x00000000
V (7577022) wl_partition: erase_range - start_address=0x00002000, size=0x00001000, result=0x00000000
V (7577022) wl_flash: erase_range - result= 0x00000000
D (7577022) wl_flash: write - dest_addr= 0x00013000, size= 0x00001000
V (7577022) wl_flash: calcAddr - addr= 0x00013000 -> result= 0x00002000, dummy_addr= 0x00000000
V (7577042) ff_diskio_spiflash: ff_wl_write - pdrv=0, sector=1, count=1

D (7577042) wl_flash: erase_range - start_address= 0x00001000, size= 0x00001000
D (7577052) wl_flash: erase_sector - sector= 0x00000001
V (7577052) wl_flash: calcAddr - addr= 0x00001000 -> result= 0x001da000, dummy_addr= 0x00000000
V (7577102) wl_partition: erase_range - start_address=0x001da000, size=0x00001000, result=0x00000000
V (7577102) wl_flash: erase_range - result= 0x00000000
D (7577102) wl_flash: write - dest_addr= 0x00001000, size= 0x00001000
V (7577102) wl_flash: calcAddr - addr= 0x00001000 -> result= 0x001da000, dummy_addr= 0x00000000
V (7577122) ff_diskio_spiflash: ff_wl_read - pdrv=0, sector=2, count=1

D (7577122) wl_flash: read - src_addr= 0x00002000, size= 0x00001000
V (7577132) wl_flash: calcAddr - addr= 0x00002000 -> result= 0x001db000, dummy_addr= 0x00000000
V (7577142) ff_diskio_spiflash: ff_wl_write - pdrv=0, sector=2, count=1

D (7577142) wl_flash: erase_range - start_address= 0x00002000, size= 0x00001000
D (7577152) wl_flash: erase_sector - sector= 0x00000002
V (7577162) wl_flash: calcAddr - addr= 0x00002000 -> result= 0x001db000, dummy_addr= 0x00000000
V (7577202) wl_partition: erase_range - start_address=0x001db000, size=0x00001000, result=0x00000000
V (7577202) wl_flash: erase_range - result= 0x00000000
D (7577202) wl_flash: write - dest_addr= 0x00002000, size= 0x00001000
V (7577202) wl_flash: calcAddr - addr= 0x00002000 -> result= 0x001db000, dummy_addr= 0x00000000
V (7577222) ff_diskio_spiflash: ff_wl_ioctl: cmd=0

2021-05-23,21:25:10,D,PWRM,<src,1,active,0.22,15mp,0.497,total,4.66,voltage,230.6,current,0.0,freq,50.0,pf,0.00
V (7577292) vfs_fat: vfs_fat_open: path="/pwrmtr-3.log", flags=2, mode=1b6
V (7577292) ff_diskio_spiflash: ff_wl_read - pdrv=0, sector=19, count=1

D (7577302) wl_flash: read - src_addr= 0x00013000, size= 0x00001000
V (7577312) wl_flash: calcAddr - addr= 0x00013000 -> result= 0x00002000, dummy_addr= 0x00000000
V (7577322) ff_diskio_spiflash: ff_wl_write - pdrv=0, sector=19, count=1

D (7577322) wl_flash: erase_range - start_address= 0x00013000, size= 0x00001000
D (7577332) wl_flash: erase_sector - sector= 0x00000013
V (7577332) wl_flash: calcAddr - addr= 0x00013000 -> result= 0x00002000, dummy_addr= 0x00000000
V (7577382) wl_partition: erase_range - start_address=0x00002000, size=0x00001000, result=0x00000000
V (7577382) wl_flash: erase_range - result= 0x00000000
D (7577382) wl_flash: write - dest_addr= 0x00013000, size= 0x00001000
V (7577392) wl_flash: calcAddr - addr= 0x00013000 -> result= 0x00002000, dummy_addr= 0x00000000
V (7577402) ff_diskio_spiflash: ff_wl_write - pdrv=0, sector=2, count=1

D (7577402) wl_flash: erase_range - start_address= 0x00002000, size= 0x00001000
D (7577412) wl_flash: erase_sector - sector= 0x00000002
V (7577412) wl_flash: calcAddr - addr= 0x00002000 -> result= 0x001db000, dummy_addr= 0x00000000
V (7577452) wl_partition: erase_range - start_address=0x001db000, size=0x00001000, result=0x00000000
V (7577452) wl_flash: erase_range - result= 0x00000000
D (7577452) wl_flash: write - dest_addr= 0x00002000, size= 0x00001000
V (7577452) wl_flash: calcAddr - addr= 0x00002000 -> result= 0x001db000, dummy_addr= 0x00000000
V (7577472) ff_diskio_spiflash: ff_wl_ioctl: cmd=0

2021-05-23,21:26:10,D,PWRM,<src,0,active,0.17,15mp,0.215,total,2.148
V (7637532) vfs_fat: vfs_fat_open: path="/pwrmtr-3.log", flags=2, mode=1b6
V (7637532) ff_diskio_spiflash: ff_wl_read - pdrv=0, sector=19, count=1

D (7637542) wl_flash: read - src_addr= 0x00013000, size= 0x00001000
V (7637542) wl_flash: calcAddr - addr= 0x00013000 -> result= 0x00002000, dummy_addr= 0x00000000
V (7637552) ff_diskio_spiflash: ff_wl_write - pdrv=0, sector=19, count=1

D (7637562) wl_flash: erase_range - start_address= 0x00013000, size= 0x00001000
D (7637562) wl_flash: erase_sector - sector= 0x00000013
V (7637572) wl_flash: calcAddr - addr= 0x00013000 -> result= 0x00002000, dummy_addr= 0x00000000
V (7637612) wl_partition: erase_range - start_address=0x00002000, size=0x00001000, result=0x00000000
V (7637612) wl_flash: erase_range - result= 0x00000000
D (7637612) wl_flash: write - dest_addr= 0x00013000, size= 0x00001000
V (7637612) wl_flash: calcAddr - addr= 0x00013000 -> result= 0x00002000, dummy_addr= 0x00000000
V (7637632) ff_diskio_spiflash: ff_wl_write - pdrv=0, sector=2, count=1

D (7637632) wl_flash: erase_range - start_address= 0x00002000, size= 0x00001000
D (7637642) wl_flash: erase_sector - sector= 0x00000002
V (7637642) wl_flash: calcAddr - addr= 0x00002000 -> result= 0x001db000, dummy_addr= 0x00000000
V (7637682) wl_partition: erase_range - start_address=0x001db000, size=0x00001000, result=0x00000000
V (7637682) wl_flash: erase_range - result= 0x00000000
D (7637682) wl_flash: write - dest_addr= 0x00002000, size= 0x00001000
V (7637682) wl_flash: calcAddr - addr= 0x00002000 -> result= 0x001db000, dummy_addr= 0x00000000
V (7637702) ff_diskio_spiflash: ff_wl_ioctl: cmd=0

2021-05-23,21:26:11,D,PWRM,<src,1,active,0.57,15mp,0.514,total,4.123,voltage,230.7,current,0.0,freq,50.0,pf,0.00
V (7637772) vfs_fat: vfs_fat_open: path="/pwrmtr-3.log", flags=2, mode=1b6
V (7637772) ff_diskio_spiflash: ff_wl_read - pdrv=0, sector=19, count=1

D (7637782) wl_flash: read - src_addr= 0x00013000, size= 0x00001000
V (7637792) wl_flash: calcAddr - addr= 0x00013000 -> result= 0x00002000, dummy_addr= 0x00000000
V (7637802) ff_diskio_spiflash: ff_wl_write - pdrv=0, sector=19, count=1

D (7637802) wl_flash: erase_range - start_address= 0x00013000, size= 0x00001000
D (7637812) wl_flash: erase_sector - sector= 0x00000013
V (7637812) wl_flash: calcAddr - addr= 0x00013000 -> result= 0x00002000, dummy_addr= 0x00000000
V (7637862) wl_partition: erase_range - start_address=0x00002000, size=0x00001000, result=0x00000000
V (7637862) wl_flash: erase_range - result= 0x00000000
D (7637862) wl_flash: write - dest_addr= 0x00013000, size= 0x00001000
V (7637872) wl_flash: calcAddr - addr= 0x00013000 -> result= 0x00002000, dummy_addr= 0x00000000
V (7637882) ff_diskio_spiflash: ff_wl_write - pdrv=0, sector=2, count=1

D (7637882) wl_flash: erase_range - start_address= 0x00002000, size= 0x00001000
D (7637892) wl_flash: erase_sector - sector= 0x00000002
V (7637892) wl_flash: calcAddr - addr= 0x00002000 -> result= 0x001db000, dummy_addr= 0x00000000
V (7637942) wl_partition: erase_range - start_address=0x001db000, size=0x00001000, result=0x00000000
V (7637942) wl_flash: erase_range - result= 0x00000000
D (7637942) wl_flash: write - dest_addr= 0x00002000, size= 0x00001000
V (7637942) wl_flash: calcAddr - addr= 0x00002000 -> result= 0x001db000, dummy_addr= 0x00000000
V (7637962) ff_diskio_spiflash: ff_wl_ioctl: cmd=0

2021-05-23,21:27:11,D,PWRM,<src,0,active,0.7,15mp,0.218,total,2.155
V (7698022) vfs_fat: vfs_fat_open: path="/pwrmtr-3.log", flags=2, mode=1b6
V (7698022) ff_diskio_spiflash: ff_wl_read - pdrv=0, sector=19, count=1

D (7698032) wl_flash: read - src_addr= 0x00013000, size= 0x00001000
V (7698032) wl_flash: calcAddr - addr= 0x00013000 -> result= 0x00002000, dummy_addr= 0x00000000
V (7698042) ff_diskio_spiflash: ff_wl_write - pdrv=0, sector=19, count=1

D (7698052) wl_flash: erase_range - start_address= 0x00013000, size= 0x00001000
D (7698052) wl_flash: erase_sector - sector= 0x00000013
V (7698062) wl_flash: calcAddr - addr= 0x00013000 -> result= 0x00002000, dummy_addr= 0x00000000
V (7698102) wl_partition: erase_range - start_address=0x00002000, size=0x00001000, result=0x00000000
V (7698102) wl_flash: erase_range - result= 0x00000000
D (7698102) wl_flash: write - dest_addr= 0x00013000, size= 0x00001000
V (7698112) wl_flash: calcAddr - addr= 0x00013000 -> result= 0x00002000, dummy_addr= 0x00000000
V (7698122) ff_diskio_spiflash: ff_wl_write - pdrv=0, sector=2, count=1

D (7698122) wl_flash: erase_range - start_address= 0x00002000, size= 0x00001000
D (7698132) wl_flash: erase_sector - sector= 0x00000002
V (7698132) wl_flash: calcAddr - addr= 0x00002000 -> result= 0x001db000, dummy_addr= 0x00000000
V (7698182) wl_partition: erase_range - start_address=0x001db000, size=0x00001000, result=0x00000000
V (7698182) wl_flash: erase_range - result= 0x00000000
D (7698182) wl_flash: write - dest_addr= 0x00002000, size= 0x00001000
V (7698192) wl_flash: calcAddr - addr= 0x00002000 -> result= 0x001db000, dummy_addr= 0x00000000
V (7698202) ff_diskio_spiflash: ff_wl_ioctl: cmd=0

2021-05-23,21:27:11,D,PWRM,<src,1,active,0.9,15mp,0.464,total,4.132,voltage,229.2,current,0.0,freq,50.0,pf,0.00
V (7698272) vfs_fat: vfs_fat_open: path="/pwrmtr-3.log", flags=2, mode=1b6
V (7698272) ff_diskio_spiflash: ff_wl_read - pdrv=0, sector=19, count=1

D (7698282) wl_flash: read - src_addr= 0x00013000, size= 0x00001000
V (7698292) wl_flash: calcAddr - addr= 0x00013000 -> result= 0x00002000, dummy_addr= 0x00000000
V (7698302) ff_diskio_spiflash: ff_wl_write - pdrv=0, sector=19, count=1

D (7698302) wl_flash: erase_range - start_address= 0x00013000, size= 0x00001000
D (7698312) wl_flash: erase_sector - sector= 0x00000013
V (7698312) wl_flash: calcAddr - addr= 0x00013000 -> result= 0x00002000, dummy_addr= 0x00000000
V (7698362) wl_partition: erase_range - start_address=0x00002000, size=0x00001000, result=0x00000000
V (7698362) wl_flash: erase_range - result= 0x00000000
D (7698362) wl_flash: write - dest_addr= 0x00013000, size= 0x00001000
V (7698372) wl_flash: calcAddr - addr= 0x00013000 -> result= 0x00002000, dummy_addr= 0x00000000
V (7698382) ff_diskio_spiflash: ff_wl_write - pdrv=0, sector=2, count=1

D (7698382) wl_flash: erase_range - start_address= 0x00002000, size= 0x00001000
D (7698392) wl_flash: erase_sector - sector= 0x00000002
V (7698392) wl_flash: calcAddr - addr= 0x00002000 -> result= 0x001db000, dummy_addr= 0x00000000
V (7698442) wl_partition: erase_range - start_address=0x001db000, size=0x00001000, result=0x00000000
V (7698442) wl_flash: erase_range - result= 0x00000000
D (7698442) wl_flash: write - dest_addr= 0x00002000, size= 0x00001000
V (7698452) wl_flash: calcAddr - addr= 0x00002000 -> result= 0x001db000, dummy_addr= 0x00000000
V (7698462) ff_diskio_spiflash: ff_wl_ioctl: cmd=0
<<<

[simonjo]

Already an update to my posting:

The instance running with only PCNT active also has a problem, it just took 24 hours to show, after that it shows following partition/file info:

2021-05-23,23:28:07,I,APPL,!Part: ota_0 APP OTA_0 00010000 00100000
2021-05-23,23:28:07,I,APPL,!Part: ota_1 APP OTA_1 00110000 00100000
2021-05-23,23:28:07,I,APPL,!Part: nvs DATA NVS 00009000 00004000
2021-05-23,23:28:07,I,APPL,!Part: otadata DATA OTA 0000d000 00002000
2021-05-23,23:28:07,I,APPL,!Part: phy_init DATA PHY 0000f000 00001000
2021-05-23,23:28:07,I,APPL,!Part: private DATA FAT 00210000 001f0000
2021-05-23,23:28:07,I,APPL,!Found file ���@
2021-05-23,23:28:07,I,APPL,!Found file PWRMTR-3.LOG

The strange thing is that the code with PCNT only has been running fine for 6 weeks in succession, the difference then was that I had a 1Mb factory partition and a 960Kb private fat partition versus now a 1984Kb private fat partition.

[simonjo]

Maybe one more detail... power is measured every minute, but the PCNT data is immediately available and written to the logfile.

Next a read command is sent to the PZEM004T and then when the reply comes in, the result is written to the logfile. This communication takes about 70ms, but could be less.

Writing of each set of data (8 bytes) is done by opening the file (fopen), writing the data (fwrite) and closing the file (fclose).

Could it be that there is some sort of lingering on fclose(), such that when the second fopen() arrives faster than 70ms it hits a file still in transition to closed state?

[ESP_Sprite]

I'm idly wondering if you're doing the writes in two different threads? Could be a concurrency issue then.

[simonjo]

Hi,

I double checked and looked for all fopen/fwrite/fclose occurences in my app and there are 2 locations found:
- the httpsd (http server for reporting)
- the pwrmtrd (power meter daemon for collecting)

Both httpsd and pwrmtrd are running in the same worker thread, which is 1 thread with a queue to handle each subtask in turn.

So when httpsd is running, then pwrmtrd is not, and when pwrmtrd is running, then httpsd is not.

It keeps appearing at random intervals and each time the logfile ends up with a corrupted name

I am backtracking all changes I made since the working version:
- add I2C functionality with RTC and OLED connected
- add PZEM004T with UART driver
- increase data partition size


Jo

[ESP_Sprite]

Hm, not sure what it could be then, sorry.

[simonjo]

Thx for your thoughts.

I am now trying with a changed algo that separate the logfile writes by 10 seconds and see if this improves it.

Ultimately I consider going for raw partition handling, just writing sectors as they fill up with in memory caching, such that you incrementally write real data to a previously erased sector. This might ultimately be the best choice for a number of reasons:
- no filesystem overhead
- get rid of the massive erase/write cycles I saw in the wl_flash debug logging, which will wear down the flash pretty soon