uSD logging causes assert in tasks.c

[whoenig]

I am using the latest master branch with a simple config.txt such as:

100   # frequency
25    # buffer size
cf50_   # file name
0     # enable on startup (0/1)
1     # mode (0: disabled, 1: synchronous stabilizer, 2: asynchronous)
stateEstimateZ.x
stateEstimateZ.y
stateEstimateZ.z

The CF reboots with SYS: Assert failed at .//vendor/FreeRTOS/tasks.c:4049 when logging is started (setting usd/logging parameter to 1). Here is an example stacktrace with gdb:

(gdb) bt
#0  xTaskPriorityDisinherit (pxMutexHolder=0x20003b30 <ucHeap+8964>) at .//vendor/FreeRTOS/tasks.c:4050
#1  0x080062c8 in prvCopyDataToQueue (pxQueue=pxQueue@entry=0x20003ca0 <ucHeap+9332>, 
    pvItemToQueue=pvItemToQueue@entry=0x0, xPosition=xPosition@entry=0) at .//vendor/FreeRTOS/queue.c:2086
#2  0x080065b0 in xQueueGenericSend (xQueue=0x20003ca0 <ucHeap+9332>, pvItemToQueue=0x0, 
    xTicksToWait=<optimized out>, xCopyPosition=0) at .//vendor/FreeRTOS/queue.c:840
#3  0x0800e534 in sendCommand (context=context@entry=0x20000f3c <sdSpiContext>, cmd=cmd@entry=24 '\030', 
    arg=27919872, arg@entry=2963932672) at .//src/drivers/src/fatfs_sd.c:147
#4  0x0800e7ce in SD_disk_write (
    buff=0x2000b680 <logFile+40> "\004tick(I),stateEstimateZ.x(h),stateEstimateZ.y(h),stateEstimateZ.z(h),<\245", <incomplete sequence \356>, sector=2963932672, count=1, usrOps=0x20000f3c <sdSpiContext>)
    at .//src/drivers/src/fatfs_sd.c:369
#5  0x0800e17c in f_sync (fp=fp@entry=0x2000b658 <logFile>) at .//src/lib/FatFS/ff.c:3683
#6  0x0800e1ec in f_close (fp=fp@entry=0x2000b658 <logFile>) at .//src/lib/FatFS/ff.c:3753
#7  0x08028286 in usdWriteTask (usdLogQueue=0x20004858 <ucHeap+12332>) at .//src/deck/drivers/src/usddeck.c:695
#8  0x08007528 in ?? () at .//vendor/FreeRTOS/portable/GCC/ARM_CM4F/port.c:703
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

I am not sure which mutex is triggering the condition. My suspicion is that the spiMutex is somehow taken in a different task and attempted to be released in another task. Note that this was not an issue in older firmware versions with the same usd_deck.c code. Thus, this must be caused by some other recent changes (e.g., FreeRTOS?).

[tobbeanton]

We are looking at this now and it triggers first when you have wither the LPS or Flow deck attached as well. Is this the case for you as well @whoenig? Maybe this is related to the old issue #270.

[whoenig]

Yes, I think I had the flow deck attached because I was testing at home.

[knmcguire]

We been trying to investigate this further. It is indeed that it is caused due to a spimutex being opened by one task and closed by another. The usddeck driver has a lot of closing and openings of the spibus mutex so it might go wrong somewhere there although it is difficult to pinpoint where it goes wrong since the fatfs_sd driver is a bit all over the place.

The sendcommand is where it goes wrong (the second deselect), and probably it deselects the flowdeck's mutex while it shouldn't while it is actually expecting it's own still operating (it is also opened it the same function...) The weird thing is though, is that FreeRtos should not even switch tasks during that time but for some reason it does.

[tobbeanton]

Further investigation shows indeed that Fatfs is giving the spimutex twice and after the flow deck has taken it. The fatfs_sd integration probably needs to be rewritten. Not designed for sharing a bus...

This issue happens now because at some point I added a systemWaitStart to start the usdlog (to fix another issue) and this is causing the flow and usdlog to run at the same time which causes this conflict.

I did a quick fix to prevent the spimutex to be given twice but it does not solve the whole problem of course, then we are back to issue #270.

[whoenig]

Even if both share the SPI bus, shouldn't the uSD deck still work at low logging frequencies? In #270 it seems like logging completely stops, which is likely a SW bug?

[tobbeanton]

This bug finally solved! See commit 46cf8db and issue #270