Bug: Using server.serveStatic causes WDT crashes almost every 2nd time for files >150K

[ullix]

I have static, binary log files which I download via WiFi. Works well most of the time, but then there are perpetual crashes. It seems the success depends on the size of the files. Up to 64k mostly ok, 64k ... 128k ok for half the trials, beyond that size almost never ok.

I am using the LittleFS file system. The files are build up of 32 bytes binary records, and may eventually grow >2MB. I use this command for downloading as static file:

// file system definition:   fs::LITTLEFSFS  * myFS       = &LITTLEFS;
server.serveStatic("/log.cam",      *myFS, "/log.cam");

I also tried this. Works just as well, but no improvement:

server.on("/log.cam", HTTP_GET, [] (AsyncWebServerRequest *request) {request->send(*myFS, "/log.cam", application/octet-stream");});

The download is triggered from a website, either as a straight link to download the binary file, or as Javascript code inside a function:

Link:   "<a href='/https/github.com/log.cam' >CAM</a>"
...
JS:   const fetchdata     = await fetch('/log.cam', {cache: "no-store"});

Your ReadMe seems to suggest that chunked responses are NOT needed for static files? So, I did not use that here. Am I forgetting any settings, or do I also need to use chunked response when the static file is beyond a certain size? Which size?

[ullix]

Upon further investigations I conclude that this is a bug. For me a very serious one as it drastically reduces download speed by a factor of more than 10!

As first test I also coded a chunked response, but as expected, it showed the same failures as reported above. However, this chunk code now allowed to define the chunk size, and this made a huge difference!

I created a 300k (307200 B) file and downloaded that in various configurations. In all tests it always crashed with a wdt message when the download touched 100000; I observed only the two values of 100030 and 101459. Message was:

E (144357) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time:
E (144357) task_wdt:  - async_tcp (CPU 1)
E (144357) task_wdt: Tasks currently running:
E (144357) task_wdt: CPU 0: IDLE0
E (144357) task_wdt: CPU 1: loopTask
E (144357) task_wdt: Aborting.
abort() was called at PC 0x401058a4 on core 0

I used various ESP32-WROOM-32E (all latest revision 3) with Flash of 4MB, 8MB, and 16MB. All gave the same result.

Using the code included below I tested for the impact of chunk size, and got a big surprise:

• 1028 Bytes chunk size : all downloads worked. Even a file of 1.2MB could be downloaded correctly!

• 1029 Bytes chunk size : only 1 Byte more and all downloads failed when the filesize was 100k or greater! Files of size 90k so far could be downloaded without problems.

I tested the file systems FFat and LittleFS. Outcome was identical.

I noticed that the download was very slow, slower by about an order of magnitude!

So I used a file of 90k, which could be downloaded under all conditions, and measured download times:

• 1028 Bytes chunk size : 3.1 sec
• 1029 Bytes chunk size : 0.4 sec
• (set by async server) : 0.2 sec (varied between 5600 and 1400 Bytes during a download)

Using 1028 Bytes makes it 15 times slower, but is the only option for big files, when you need speed most!

And one last surprise: removing the print options in chunk-code made it even slower, not faster!

Here is the relevant code:

// File system
// either:
    fs::F_Fat       * myFS       = &FFat;
// or:
    fs::LITTLEFSFS  * myFS       = &LITTLEFS;



// ESPAsyncWebServer setup
    server.on("/log.cam",       HTTP_GET, [] (AsyncWebServerRequest *request) { staticDataType = CAM;
                                                                                request->sendChunked(text_plain, onStaticDownLoad);});

// chunk code
size_t onStaticDownLoad(uint8_t *buffer, size_t maxLen, size_t index){

    static  char *   filename;                 // file to be sent as chunks
    static  File     chunkfile;                // file handle of filename
    static  size_t   dnlLen     = 1028;        // limit to buffer size
            uint32_t countbytes = 0;           // bytes to be returned

    if (index == 0)  {
        if (staticDataType == CAM)  filename    = LOGCAM;
        else                        filename    = LOGCPS;
        samm->printf("onStaticDownLoad: START filename: %s index: %6i maxLen: %5i\n", filename, index, maxLen);
        chunkfile       = myFS->open(filename);
    }

    chunkfile.seek(index);
    countbytes = chunkfile.read(buffer, min(dnlLen, maxLen));

    if (countbytes == 0) {
        chunkfile.close();
    }
    samm->printf("onStaticDownLoad: f: %s index: %6u maxLen: %5u countb: %5u \n"
                    , filename
                    , index
                    , maxLen
                    , countbytes
                );

    return countbytes;
}

[ullix]

This is still a major problem for me, so I investigated further. To simplify I only used the webserver with command

server.serveStatic("/bindataST",      *myFS, "/data.cam");

and only on ESP32-WROOM-32E (revision3, the latest models) with 4MB Flash with the LittleFS file system. I created binary data files of various sizes. (While saved in binary mode, all bytes were printable ASCII, so the file content was legible to humans).

The data shown below were compiled with Arduino 2.0 beta 7, and ESP core 1.0.6, but I repeated some tests with Arduino 1.8.13 and ESP core 1.0.4 and got same results.

I automated this by creating an auto-refreshing website containg JavaScript, by which a serveStatic function of the webserver was called, and logged to the Serial Terminal.

Up to a file size of 150 Kibibytes all downloads were always successful. In an overnight run with a 90KB file all 15833 downloads were successful, not a single failure.

However, with only a few bytes more, 160 Kibibytes, the number of Watch-Dog-Timer induced crashes increased progressively. All were of the same type:

E (69589) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time:
E (69589) task_wdt:  - async_tcp (CPU 1)
E (69589) task_wdt: Tasks currently running:
E (69589) task_wdt: CPU 0: IDLE0
E (69589) task_wdt: CPU 1: loopTask
E (69589) task_wdt: Aborting.
abort() was called at PC 0x4014246c on core 0

The successful downloads decreased to as low as 58%, i.e. almost every 2nd download attempt resulted in a crash and reboot! Somewhat strangely, beyond a file size of ~300K the success rate increased a little bit, and was 70% at 1.4MB, the biggest file possible in this setting.

As I had mentioned on previous posts, one can mitigate this WDT problem by using chunked downloads. However, this slows down the transfer drastically by 40...50 times! Here are two examples done subsequently:

This shows the web page result for serveStatic (picking one when it worked!):

Binary Data in Human-Readable Format
#Total: 1433600 bytes, 1400 kB, 44800 records, dur: 2834 ms, speed: 506 kB/s
1 0123456789ABCDEFGHIJKLMNOPQRSTUV
2 0123456789ABCDEFGHIJKLMNOPQRSTUV

A speed of 506 kB/s is very nice; top-speed observed was even a fantastic ~800kB/s!

With a chunked download you need to limit the maxLen of the chunk to 1028 bytes, or you face again the WDT crash issue. With that limit this is what you get:

Binary Data in Human-Readable Format
#Total: 1433600 bytes, 1400 kB, 44800 records, dur: 124706 ms, speed: 11 kB/s
1 0123456789ABCDEFGHIJKLMNOPQRSTUV
2 0123456789ABCDEFGHIJKLMNOPQRSTUV

Instead of 3 sec it now takes over 2 min, a speed of only 11 kB/s!

I am building a device which logs data, and I will use even the bigger 8MB and 16MB ESP variants and files filling the Flash. This webserver cannot handle this!

[BlueAndi]

You download the files in the context of the web server (Async TCP task). Did you try to move it to the loop context?

[ullix]

@BlueAndi How can I do this? I think it is not possible, but please, correct me.

My webserver initialization gets this code:

AsyncWebServer      server(80);
void initWebServer() {
    ...
    server.serveStatic("/bindataST",      *myFS, "/data.cam");
    server.begin(); 
}

Then from a website I call <ESP-IP>/bindataST to download file "data.cam" from my file system LittleFs. That's it. Which part can I relocate?

[BlueAndi]

You can't do this with serveStatic(), but you can handle the request by your own.
Please note, below is just a rough principle I could imagine, which would be worthful to check. To be task safe, you can later use a freeRTOS queue, instead of a deferredRequest variable.

static AsyncWebServerRequest* deferredRequest = nullptr;

static void downloadPage(AsyncWebServerRequest* request)
{
    deferredRequest = request;
}

...
void setup()
{
    ...
    server.on("/bindataST/data.cam", HTTP_GET, downloadPage);
    server.begin();
    ...
}

...
void loop()
{
    ....
    if (nullptr != deferredRequest)
    {
        deferredRequest->send(LITTLEFS, "/bindataST/data.cam", String(), true);
        deferredRequest = nullptr;
    }
    ...
}

[zekageri]

Wow. This is gold

[ullix]

That sure is an idea! I hadn't expected it is possible. But it works.

However, only to a degree.

I put this in my code and tested file sizes up to 1400k on my ESP32-WROOM-E with 4MB Flash. The most sensitive file size range as shown in my graph above #984 (comment) seemed to be around 300k. And again, with 200 ... 300 downloads on each file size, I saw WDT crashes only at 300k and 400k, but it did crash.

Then I pulled out my ESP32-WROOM-E with 16MB Flash and created a 12MB(!) file, and repeatedly downloaded over night. The downloads were a very decent 650kB/s, but that still takes near 20sec. But this time almost 20% of all download attempts crashed with a triggered Watch-Dog-Timer following the command
deferredRequest->send(*myFS, "/data.cam", String(), true);:

Loop: deferredRequest handling
E (30449) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time:
E (30449) task_wdt:  - async_tcp (CPU 0/1)
E (30449) task_wdt: Tasks currently running:
E (30449) task_wdt: CPU 0: IDLE0
E (30449) task_wdt: CPU 1: loopTask
E (30449) task_wdt: Aborting.
abort() was called at PC 0x40140ae4 on core 0

What I find strange is the async_tcp (CPU 0/1) message. What does it mean? Is the WDT triggered from both CPU cores at exactly the same time? Out of a total of 293 crashes, 292 were of this (CPU 0/1) type, and only 1 of (CPU 1) type, none of (CPU 0) type.

So, while greatly improved, this is not the final solution. What else can I do?

[zekageri]

This seems the common async server crash problem to me.

Can you replace the ESPAsyncWebServer lib with this forked version by Depau and try again?

I'm currently testing this fork and it seems very stable

[ullix]

I'll try. Looking at both ReadMEs, the Depau version seems to be taken verbatim from me-no-dev. Where is the difference in the code? Which part is changed?

One other thing bothers me: Both parties offer their code is explicitly for ESPs. I learned that neither PROGMEM nor the F() macro make any sense on these CPUs (https://www.esp32.com/viewtopic.php?f=19&t=20595 ). Yet, both offerings expressly advertise for PROGMEM and for F(). Are they not aware of this? I don't believe that. So, why this nonsense?

[zekageri]

Here is the PR by Depau He fixed some linked list problems and things like that.

About the PROGMEM and F() things i don't know. Probably compatibility solutions between esp8266 and esp32 and things like that. There are so many esps around, you never know what was Me_no_dev's intention with these.

[zekageri]

I'll try. Looking at both ReadMEs, the Depau version seems to be taken verbatim from me-no-dev.

Yes. It is a fork from me-no-dev's lib. The readme and almost everything is the same except the linked list and some other fixes.

[Pablo2048]

One other thing bothers me: Both parties offer their code is explicitly for ESPs. I learned that neither PROGMEM nor the F() macro make any sense on these CPUs (https://www.esp32.com/viewtopic.php?f=19&t=20595 ). Yet, both offerings expressly advertise for PROGMEM and for F(). Are they not aware of this? I don't believe that. So, why this nonsense?

The reason for this is compatibility - ESP8266 requires using PROGMEM/F() if you don't want to waste the RAM. Definitely NOT a nonsense...

[ullix]

Getting the Depau lib is not very promising, so far:

I downloaded the ZIP which gave me a file of this name: ESPAsyncWebServer-partial-header.zip. The 'partial' is irritating, but I tried several times and Firefox tells me the download had correctly completed.

The tried to install in Ar1.8.13 and got this message:

I tried Ar2.0beta7 and got this:

Then I tried $ gh repo clone Depau/ESPAsyncWebServer and got this:
ERROR: ld.so: object 'libgtk3-nocsd.so.0' from LD_PRELOAD cannot be preloaded (failed to map segment from shared object): ignored.

Now, what?