request handler panic in core_esp8266_main.cpp when using readString on SPIFFS #1

andig · 2016-01-20T11:05:23Z

me-no-dev · 2016-01-20T11:10:04Z

The main problem is that you use readString() which calls yield internally ( not optimistic_yield like SPIFFS) so you always try to switch the context and that triggers the panic. Try to read the bytes into a char buffer and turn that into a string if you need to manipulate the string.

andig · 2016-01-20T11:27:12Z

Seems read with String signature is forbidden as well. I'll try with char[]. Would be good to add this to a "basic" example, also showing the on() syntax with callbacks.

me-no-dev · 2016-01-20T11:30:15Z

yeah, I'll look into those a you showed a problem I did not expect :) have you tried casting the callback?

g_server.on("/index.html", (ArRequestHandlerFunction)handleRoot);

also you handleRoot is defined above where you attach on() right?

me-no-dev · 2016-01-20T11:33:14Z

if we fix the core to not yield all of the time maybe you will be able to use the String functions :) I prefer that, than showing workarounds

andig · 2016-01-20T11:48:26Z

I've got this now (omitting the prints):

char *buf = (char *)malloc(indexFile.size()+1);
indexFile.read((uint8_t *)buf, indexFile.size());
buf[indexFile.size()] = '\0';
indexHTML = String(buf);
free(buf);

but it gets stuck:

[webserver] uri: / args: 0
[core] heap: 26920
[webserver] file read, size: 6981
[core] heap: 19824
[core] heap: 12944
[webserver] file close
[webserver] content length: 6981
E:M 7000

It's also quite ugly that we need the memory twice- for buffer and string. Any ideas?

ps.: cast is fine!

me-no-dev · 2016-01-20T11:52:09Z

What are you using the string for? Maybe I can give ideas if I know more of what you want to acomplish with it :) also above you free the buf, but you might be doing it too soon? what is E:M 7000 ? :D never seen that

me-no-dev · 2016-01-20T11:53:27Z

can you hack into Print.cpp in the core and remove the yield inside timedRead and see if you can use the readString()

andig · 2016-01-20T13:28:21Z

What are you using the string for?

I'm just using it to run some replacements:

char buff[10];
uint16_t s = millis() / 1000;
uint16_t m = s / 60;
uint8_t h = m / 60;
snprintf(buff, 10, "%02d:%02d:%02d", h, m % 60, s % 60);

// replace placeholder
indexHTML.replace("[build]", BUILD);
indexHTML.replace("[esp8266]", String(ESP.getChipId(), HEX));
indexHTML.replace("[uptime]", buff);
indexHTML.replace("[ssid]", g_ssid);
indexHTML.replace("[wifimode]", (WiFi.getMode() == WIFI_STA) ? "Connected" : "Access Point");

Most things are json services, but some data is required upfront.

can you hack into Print.cpp in the core

Mhm. Can't find yield in Print? Rather Stream.cpp? Changing yield to optimistic_yield(10) in Stream::timedRead() didn't work either.

what is E:M 7000 ? :D never seen that

Must be coming from core or sdk. Apparently telling me that my sketch is borked :(

me-no-dev · 2016-01-20T13:30:03Z

optimistic_yield should be 10000 or more

andig · 2016-01-20T13:42:43Z

Same result using readString with Stream.cpp patched like this:

int ICACHE_FLASH_ATTR Stream::timedRead() {
    int c;
    _startMillis = millis();
    do {
    c = read();
    if(c >= 0)
        return c;
      // yield();
      optimistic_yield(OPTIMISTIC_YIELD_TIME_US);
    } while(millis() - _startMillis < _timeout);
    return -1;     // -1 indicates timeout
}

I'm lost...

me-no-dev · 2016-01-20T14:01:43Z

what about without any yield at all

andig · 2016-01-20T15:28:12Z

what about without any yield at all

Same thing. scratch head

me-no-dev · 2016-01-20T15:30:51Z

scratching head as well
can you gist me the sketch so I can load it here and try it.

andig · 2016-01-20T15:55:50Z

The longer I keep looking the more I think its is in the wrong place. This:

void handleRoot(AsyncWebServerRequest *request)
{
  DEBUG_SERVER("[webserver] uri: %s args: %d\n", request->url().c_str(), request->params());
  String indexHTML = F("<!DOCTYPE html><html><head><title>File not found</title></head><body><h1>File not found.</h1></body></html>");
  DEBUG_HEAP;

  request->send(200, "text/html", indexHTML);
}

produces this:

[core] heap: 30080
[webserver] uri: / args: 0
[core] heap: 25952
[webserver] uri: / args: 0
[core] heap: 25928
pm open,type:2 0
[webserver] uri: / args: 0
[core] heap: 23744
[webserver] uri: / args: 0
...repeated
[core] heap: 15320
[webserver] uri: / args: 0
...repeated
[core] heap: 14336
[webserver] uri: / args: 0
...repeated
[core] heap: 12032
e:-8:0
3fff78e0 already freed
3fff78f0 already freed
3fff78b0 already freed
3fff78c0 already freed

I'll build a minimal sketch for you.

andig · 2016-01-20T17:52:07Z

See http://pastebin.com/5MktDN10 and https://gist.github.com/andig/4797200d6bfb1fd4560b
Log produced by using Chrome on Windows and keeping finger on Ctrl-R to reload /
It's loosing memory and eventually crashing. If that's the overload in the MAC layer I'm uncertain how to differentiate from other issues?

andig · 2016-01-20T20:20:29Z

If you update the handler function from the last example like this:

void handleRoot(AsyncWebServerRequest *request)
{
  String indexHTML = F("<!DOCTYPE html><html><head><title>Test</title></head><body><h1>Test</h1></body></html>");
  char *buf;
  File indexFile = SPIFFS.open(F("/index.html"), "r");
  if (indexFile) {
//    indexHTML = indexFile.readString();
    buf = (char*)malloc(indexFile.size()+1);
    if (buf) {
      indexFile.read((uint8_t *)buf, indexFile.size());
      buf[indexFile.size()] = '\0';
      Serial.println(ESP.getFreeHeap());
    }
    indexFile.close();
  }

  indexHTML = String(buf);

  request->send(200, "text/html", indexHTML);
  if (buf)
    free(buf);
}

It will immediately crash. String is the offender. If you leave out the buffer to string part it will be fine.

What prevents String(s), apart from readString from working inside the AsyncBasicResponse?

andig · 2016-01-20T20:46:06Z

Last update for today: if I put the read/ string conversion part into setup() in addition, sketch does no longer crash. It almost seems as if SPIFFS/Strings need some sort of warmup. Really confusing.

me-no-dev · 2016-01-20T21:41:33Z

if it's in setup it is running on the loop thread and there things are fine. It's something else and I'll investigate it :) have to make it work

me-no-dev · 2016-01-20T22:08:44Z

following is the exact handler I have attached to test your function. I have 0 problems, response time is 80-90ms and webpage shows as expected. I do not Serial.print ;)

oh and no leaks either

  server.on("/test", [](AsyncWebServerRequest *request){
    String indexHTML = F("<!DOCTYPE html><html><head><title>Test</title></head><body><h1>Test</h1></body></html>");
    File indexFile = SPIFFS.open(F("/index.html"), "r");
    if (indexFile) {
      //indexHTML = indexFile.readString();
      char *buf = (char*)malloc(indexFile.size()+1);
      if (buf) {
        indexFile.read((uint8_t *)buf, indexFile.size());
        buf[indexFile.size()] = '\0';
      }
      indexFile.close();
      indexHTML = String(buf);
      free(buf);

      char buff[10];
      uint16_t s = millis() / 1000;
      uint16_t m = s / 60;
      uint8_t h = m / 60;
      sprintf(buff, "%02d:%02d:%02d", h, m % 60, s % 60);

      // replace placeholder
      indexHTML.replace("[esp8266]", String(ESP.getChipId(), HEX));
      indexHTML.replace("[uptime]", buff);
      indexHTML.replace("[ssid]", WiFi.SSID());
      indexHTML.replace("[wifimode]", (WiFi.getMode() == WIFI_STA) ? "Connected" : "Access Point");
    }


    request->send(200, "text/html", indexHTML);
  });

index.html

<!DOCTYPE html>
<html>
  <head>
    <title>Hello SPIFFS</title>
  </head>
  <body>
    <h2>ESP8266</h2>
    <h3>ChipID: [esp8266]</h3>
    <h3>Uptime: [uptime]</h3>
    <h3>SSID: [ssid]</h3>
    <h3>Mode: [wifimode]</h3>
  </body>
</html>

andig · 2016-01-21T10:19:30Z

Much appreciated. I've only had time for a quick test this morning and can confirm that it didn't crash. Moving back to additional steps I could get the crash again and immediately.

If you have 10 minutes could you also test these changes:

match on /index.html instead of /test (should work)
move handler to function, call via type cast (should work)
have ArduinoOTA.handle() in the loop() (not sure)

I'll retest the same tonight.

me-no-dev · 2016-01-21T12:30:56Z

I have the OTA running at all times. It will not interfere with the server at all :)
I have tested downloads while OTA is uploading
point 1 and 2 will work :) I have more stuff on the server, thus I used "/test"
Keep in mind to not Serial.print in the callbacks!
I've been rooting for Serial to go using only it's own buffers, so no interrupts are used and can be printed inside interrupt routines and igrr agrees so far :) My ESP31B repo uses that type of serial ;)
But till then I use a small hack in my ino to make os_printf go that way
How I do it is in the example for the WebServer :)

me-no-dev · 2016-01-21T15:13:27Z

hah! I got the email but your message is not here
I wil surely retest! what the heck

andig · 2016-01-21T15:22:40Z

hah! I got the email but your message is not here

Yes, forgive me. Every time I think I've found a pattern its gone on retest. Don't want you chasing red herrings...

andig · 2016-01-21T15:34:56Z

Ok. More tests. Working every time, regardless of how I call the handler, with your index.html.
Crashing most of the time with my bigger index.html (https://raw.githubusercontent.com/andig/vzero/master/data/index.html).

Assumption: timing issue due to the bigger file. As ESP has 40k of free RAM definitely not out of memory. If you can't repro with my file, maybe duplicate the file content.

me-no-dev · 2016-01-21T15:41:05Z

6 684 bytes while it might be under the available RAM it's more than you can easily allocate at the same time and work on. It's quite the size for transferring as string as well. On the way out you pass through a few buffers and they add to the momental ram usage...
It all makes sense on a normal MCU, but things are different here. As example I have never been able to allocate more than 4096 bytes at a time.
Other than that there is no limitation in the lib how big the string can be.

me-no-dev · 2016-01-21T17:55:01Z

When you read your big html, does it come out ok? like have you tried reading it in the loop and printing the result to serial for example?

andig · 2016-01-21T18:01:51Z

still testing ..

andig · 2016-01-21T18:24:39Z

Ok. These are the results. I can work reliably with buffers of around 4kb size with the logic above (allocate, read, convert to string, replace). That also means that in the process we need at least 2x4kb memory for buffer+string or string+replacement string.
With full size 6.6kb file it fails all the time.

I've then hacked WString to be able to write to it's internal buffer directly plus I've added pre-allocation of that buffer to consume memory only once:

if (indexFile) {
  //indexHTML = indexFile.readString();
  int size = indexFile.size();
  if (indexHTML.reserve(size + 128)) {
    // readstring into internal, preallocated buffer
    char *buf = (char*)indexHTML.c_str();
    indexFile.read((uint8_t *)buf, size);
    buf[size] = '\0';
    indexHTML.setLength(size);
    indexFile.close();

    char buff[10];
    uint16_t s = millis() / 1000;
    uint16_t m = s / 60;
    uint8_t h = m / 60;
    sprintf(buff, "%02d:%02d:%02d", h, m % 60, s % 60);

    // replace placeholder
    indexHTML.replace("[esp8266]", String(ESP.getChipId(), HEX));
    indexHTML.replace("[uptime]", buff);
    indexHTML.replace("[ssid]", WiFi.SSID());
    indexHTML.replace("[wifimode]", (WiFi.getMode() == WIFI_STA) ? "Connected" : "Access Point");
  }
}

That approach will only use the buffer once. While working at 4k it still fails at 6.6k most of the time.

I believe this is some indication that the root cause is a timing problem rather than a memory problem.

If you agree- could anything be done about that?

If not then I understand enough now on how to change the architecture of my html and js...

me-no-dev · 2016-01-21T20:03:08Z

I don't think it's timing as the server can very well send much larger content.
Can you manipulate and print that html file outside of the server? just for test to read and change the stuff then print it on the serial.

me-no-dev · 2016-01-21T20:18:48Z

and are you saying that you sometimes can allocate that 6.6k, replace the stuff inside and send out successfully?

andig · 2016-01-21T21:20:13Z

Would this be a location where to check for buffer allocation failing:

ESPAsyncWebServer/src/WebResponses.cpp

Line 223 in 1e7b944

uint8_t *buf = (uint8_t *)malloc(outLen);

?

me-no-dev · 2016-01-21T21:22:31Z

I'm going through the code wandering what it might be. I impose no restriction in the handler on the length of the string, but I do copy it since it's async and will return back to you and you will free your string. So maybe allocating over 8k at a time is a problem? who knows...
And on the last question, NO, you send basic response and it does not derive from abstract that you show.

me-no-dev · 2016-01-21T21:26:30Z

I was thinking of having that string outside and using a callback response to send it in chunks.
you can send(String contentType, size_t len, AwsResponseFiller callback) and use the response filler to read the string. It will ask you to fill a buffer (the one you showed) with as much as the tcp can currently take.
But that kinda defeats the purpose of having such large dynamic page right :)
By the way, the server is quite quick, so you can try ajaxing any dynamic info. That would be really fast :)

andig · 2016-01-21T21:54:32Z

Yeah, you're right- I guess we just give up on this one and I change the implementation. Async is blazingly fast in comparison, excellent job!

Am 21.01.2016 um 22:26 schrieb Me No Dev notifications@github.com:

I was thinking of having that string outside and using a callback response to send it in chunks.
you can send(String contentType, size_t len, AwsResponseFiller callback) and use the response filler to read the string. It will ask you to fill a buffer (the one you showed) with as much as the tcp can currently take.
But that kinda defeats the purpose of having such large dynamic page right :)
By the way, the server is quite quick, so you can try ajaxing any dynamic info. That would be really fast :)

—
Reply to this email directly or view it on GitHub.

me-no-dev · 2016-01-21T22:02:57Z

I'm beating my head currently because I have problems with 1.5.1 when uploading large files and my file system is already full of deleted pages (if you have any idea how spiffs works). So when that hits, writes to the file system slow down and lwip loses packets on retransmission because it can not handle the new packets so quick anymore. sdk 1.3 is fine and never loses a beat, but the networking on it is 3 times slower :(

andig · 2016-01-21T22:37:10Z

Sounds a little like my original issue where igor said its memory loss/ corruption inside the mac layer. Sounds like the kind of shaky basis that you really don't want to build one...

andig · 2016-01-21T22:42:19Z

My feeling is that the network layer is somewhat borked. Isnt your scenario exactly what tcp send/receive window scaling is responsible for?

me-no-dev · 2016-01-21T22:50:30Z

yes. on tcpdump all looks fine. The esp asks for retransmission and gets it, ut either the retransmitted packets or some other packets there get lost somewhere. Just lost! the Async TCP digs about as far down as maybe even too far, but still do not get the packet. SO they broke something ;) 1.3 is fine with the same behavior on the stack

andig · 2016-01-22T18:37:23Z

Would you happen to be in Germany for a beer?

me-no-dev · 2016-01-22T18:39:12Z

sadly no :( about 2K kilometers far

andig · 2016-01-22T18:41:05Z

Let me know- I owe you. If you're into smart metering feel free to take a look at http://volkszaehler.org, an opens source smart meter where I'm part of the dev team.

me-no-dev · 2016-01-22T18:43:48Z

you know anything about RS434? I have a module and power meter but no clue how to talk to it. No docs and what I have found so fat on internet is not much

andig · 2016-01-22T19:13:15Z

Let me ask my hardware genius ;)

On Fri, Jan 22, 2016 at 7:43 PM, Me No Dev notifications@github.com wrote:

you know anything about RS434? I have a module and power meter but no clue
how to talk to it. No docs and what I have found so fat on internet is not
much

—
Reply to this email directly or view it on GitHub
#1 (comment)
.

andig · 2016-01-22T20:07:06Z

Do you mean rs485? What type of module and meter, any docs?

me-no-dev · 2016-01-22T20:09:47Z

yeah :( if I had docs... I have a couple of those, they measure electrical consumption. Have RS and pulse output and an LCD. All came in a blank box. No docs. I was hoping there is some standard way to talk to those

andig · 2016-01-22T20:41:21Z

No model on the meter or module? Photo?

me-no-dev · 2016-01-22T20:44:08Z

http://kwh.en.alibaba.com/product/1051594681-219183419/DRS_205C_single_phase_din_rail_MODBUS_M_bus_energy_meter.html

andig · 2016-01-23T09:18:42Z

I think the problem is the modbus/mbus protocol. There are several libraries around but I've not managed to understand the differences. You could however use the S0 output, connected to gpio via optical transforder and count the s0 impulses?

me-no-dev · 2016-01-23T09:40:32Z

I was hoping to get more information than that from the device. It keeps tracks of things inside and I imagine that data is available through the RS

Set compatibility only with Espressif 32

…response-finished-pull-try1 Explicitly close socket after response has entered finished state

Manual merge from anton-zolotarev:master

andig closed this as completed Jan 22, 2016

Bmooij pushed a commit to Bmooij/ESPAsyncWebServer that referenced this issue Oct 14, 2019

Merge pull request me-no-dev#1 from ivankravets/patch-1

fd525d2

Set compatibility only with Espressif 32

iafilius mentioned this issue Oct 28, 2019

AsyncEvents/ServerSideEvents: prevent internal DOS by prevent overflowing messageQueue #621

Merged

Civilduino mentioned this issue Apr 6, 2020

ESP32 websocket crash at AsyncClient::space() #739

Closed

CircuitSetup pushed a commit to CircuitSetup/ESPAsyncWebServer that referenced this issue Sep 4, 2020

Merge pull request me-no-dev#1 from yubox-node-org/explicit-close-on-…

8aefa08

…response-finished-pull-try1 Explicitly close socket after response has entered finished state

gorec2005 pushed a commit to gorec2005/ESPAsyncWebServer that referenced this issue Nov 21, 2020

Merge pull request me-no-dev#1 from DmytroKorniienko/master

3cf93d7

Manual merge from anton-zolotarev:master

MichielfromNL mentioned this issue May 10, 2021

Chunked response with templates calls callback after returning 0 #969

Closed

Stumblor mentioned this issue Jun 9, 2021

Chunked Response - Guru Meditation Error: Core 1 panic'ed (Interrupt wdt timeout on CPU1) #1002

Closed

agners pushed a commit to agners/ESPAsyncWebServer that referenced this issue Jul 26, 2021

Fix EventSource ::send (me-no-dev#1)

40c37b9

sunberrysolar mentioned this issue Jun 3, 2022

ESP32 reboot after some 100-300-times web page loading (using ESPAsyncWebServer & AsyncTCP) #1037

Closed

gibo77 mentioned this issue Dec 19, 2022

Exception (3) crashes in umm_malloc_core #1251

Open

request handler panic in core_esp8266_main.cpp when using readString on SPIFFS #1

request handler panic in core_esp8266_main.cpp when using readString on SPIFFS #1

Comments

andig commented Jan 20, 2016

me-no-dev commented Jan 20, 2016

andig commented Jan 20, 2016

me-no-dev commented Jan 20, 2016

me-no-dev commented Jan 20, 2016

andig commented Jan 20, 2016

me-no-dev commented Jan 20, 2016

me-no-dev commented Jan 20, 2016

andig commented Jan 20, 2016

me-no-dev commented Jan 20, 2016

andig commented Jan 20, 2016

me-no-dev commented Jan 20, 2016

andig commented Jan 20, 2016

me-no-dev commented Jan 20, 2016

andig commented Jan 20, 2016

andig commented Jan 20, 2016

andig commented Jan 20, 2016

andig commented Jan 20, 2016

me-no-dev commented Jan 20, 2016

me-no-dev commented Jan 20, 2016

andig commented Jan 21, 2016

me-no-dev commented Jan 21, 2016

me-no-dev commented Jan 21, 2016

andig commented Jan 21, 2016

andig commented Jan 21, 2016

me-no-dev commented Jan 21, 2016

me-no-dev commented Jan 21, 2016

andig commented Jan 21, 2016

andig commented Jan 21, 2016

me-no-dev commented Jan 21, 2016

me-no-dev commented Jan 21, 2016

andig commented Jan 21, 2016

me-no-dev commented Jan 21, 2016

me-no-dev commented Jan 21, 2016

andig commented Jan 21, 2016

me-no-dev commented Jan 21, 2016

andig commented Jan 21, 2016

andig commented Jan 21, 2016

me-no-dev commented Jan 21, 2016

andig commented Jan 22, 2016

me-no-dev commented Jan 22, 2016

andig commented Jan 22, 2016

me-no-dev commented Jan 22, 2016

andig commented Jan 22, 2016

andig commented Jan 22, 2016

me-no-dev commented Jan 22, 2016

andig commented Jan 22, 2016

me-no-dev commented Jan 22, 2016

andig commented Jan 23, 2016

me-no-dev commented Jan 23, 2016