[BUG] Startup problems when lots of serial data is send to the ESP3D board during startup

[rondlh]

Describe the bug
Using ESP3D V3.0, I noticed that when a lot of serial data is generated during the startup of ESP3D then the board might lockup or restart.

I recently developed a motherboard bootloader that I put into test mode to see if everything works reliably.
During the test the bootloader repeatedly send some text like below to the ESP3D.

Bootloader started
Device mounted
Comparing firmware to flash contents.
======================================================== Equal
Firmware file and flash contents are equal, no update required

This message repeats about once a second. The ===... are send 1 character at a time like a progress bar.

I noticed that the ESP3D will not connect as a client to the wifi network if this serial data is send during its startup process. I also noticed that if I block the messages and let the ESP3D connect to the wifi network, that the serial messages are never shown on the web terminal.

Expected behavior

1. Connect to the Wifi as AP even if serial data is incoming
2. Show the serial data in the web terminal even if the data is send quite quickly

ESP3D Firmware:

• ESP3D FW version: 3.0.0-4b1.M2.1
• ESP3D-WebUI Version: 3.0.0.2b1
• Wifi mode: AP
• Flash method: build in PlatformIO, flashed OTA

Target Firmware:

• Name: Marlin
• Version 2.0

Board used (please complete the following information):

• MCU: ESP32-S2
• Name: Wemos ESP32-S2 mini V1.0.0
• Flash size: 4M + 2MB PSram

========================================================
I have a quick look into the code and found a potential issue in serial_service_esp32.cpp

void ESP3DSerialService::receiveCb() {
  if (!started()) {
    return;
  }
  if (xSemaphoreTake(_mutex, portMAX_DELAY)) {
    uint32_t now = millis();
    while ((millis() - now) < SERIAL_COMMUNICATION_TIMEOUT) {
      if (Serials[_serialIndex]->available()) {
        _buffer[_buffer_size] = Serials[_serialIndex]->read();
        now = millis();
        if (esp3d_string::isRealTimeCommand(_buffer[_buffer_size])) {
          flushChar(_buffer[_buffer_size]);
          _buffer[_buffer_size] = '\0'; //remove realtime command from buffer
        } else {
          _buffer_size++;
          if (_buffer_size > ESP3D_SERIAL_BUFFER_SIZE ||
              _buffer[_buffer_size - 1] == '\n') {
            flushBuffer();
          }
        }
      }
    }
    xSemaphoreGive(_mutex);
  } else {
    esp3d_log_e("Mutex not taken");
  }
}

receiveCb() will never exit when serial data is send at a fast rate (faster than SERIAL_COMMUNICATION_TIMEOUT = 500 ms). I'm not sure if this will call a buffer overrun and cause the crash/restart that I'm seeing.
In normal 3D printer/CNC operation this can probably never happen.
Perhaps it's better to exit the while loop when the buffer is full (_buffer_size > ESP3D_SERIAL_BUFFER_SIZE).

[luc-github]

well there is :

if (_buffer_size > ESP3D_SERIAL_BUFFER_SIZE ||
              _buffer[_buffer_size - 1] == '\n') {
            flushBuffer();
          }

so when buffer is full it is flushed
What is boot delay of ESP3D ?
Did you try to set the boot delay of ESP3D to 0 ?

[rondlh]

well there is :

if (_buffer_size > ESP3D_SERIAL_BUFFER_SIZE ||
              _buffer[_buffer_size - 1] == '\n') {
            flushBuffer();
          }

so when buffer is full it is flushed What is boot delay of ESP3D ? Did you try to set the boot delay of ESP3D to 0 ?

Right, but that still doesn't exit the while loop, and I see nothing arriving at the terminal even if the ESP3D is connected to the wifi network. When staying in the while loop, a lot of tasks do not get attention.
In esp3d_settings.cpp I have:
#define MAX_BOOT_DELAY 40000
#define MIN_BOOT_DELAY 0
#define DEFAULT_BOOT_DELAY "10000"

I played around with the bood delay some time ago (not sure if it was on v3 or v2.1) and found that if I reduce the boot delay, then connecting at start up becomes unreliable and it might fail to connect to the wifi network completely, and goes to setup mode.
UPDATE:
I tried a boot delay of 0, this doesn't change the results. The ESP3D doesn't connect to the network and the messages do not reach the terminal, I think this is because the above mentioned while loop is never exited.

[luc-github]

then add return; after the flush command flushBuffer(); to test your guess because I cannot duplicate on my side

[rondlh]

then add return; after the flush command flushBuffer(); to test your guess because I cannot duplicate on my side

My situation is a bit special, because under normal circumstances the motherboard will not generate serial data as fast a my bootloader is doing.

To duplicate you can just let the motherboard create a serial character every 100ms, and then a '\n' after let's say 60 characters to jump to the next line. The program will stay inside the while loop indefinitely, and I can see that the flushed data never arrives in the terminal, and I can see the ESP32 locks up or restarts, so I expect that somewhere data is written out of bounds.
I will do some test to see what is going wrong.

For now I managed to get thing working quite nicely by lowering SERIAL_COMMUNICATION_TIMEOUT and FLUSHTIMEOUT to 50ms. Then my problems are gone and the response time is greatly improved. Do we actually needs 500ms for the timeouts?

[luc-github]

the original value come from https://github.com/espressif/arduino-esp32/blob/master/libraries/ESP32/examples/Serial/onReceiveExample/onReceiveExample.ino

I am guessing the buffer is filled when read because your overflow it , reduce the timout means cut the data string

Does this version solve your issue when not changing the timeout ? This version only peek what it available when callback is called so there is not infinite loop possible

void ESP3DSerialService::receiveCb() {
  if (!started()) {
    return;
  }
  if (xSemaphoreTake(_mutex, portMAX_DELAY)) {
    uint32_t now = millis();
    size_t count = Serials[_serialIndex]->available();
    while ((millis() - now) < SERIAL_COMMUNICATION_TIMEOUT && count > 0) {
        _buffer[_buffer_size] = Serials[_serialIndex]->read();
        count--;
        now = millis();
        if (esp3d_string::isRealTimeCommand(_buffer[_buffer_size])) {
          flushChar(_buffer[_buffer_size]);
          _buffer[_buffer_size] = '\0'; //remove realtime command from buffer
        } else {
          _buffer_size++;
          if (_buffer_size > ESP3D_SERIAL_BUFFER_SIZE ||
              _buffer[_buffer_size - 1] == '\n') {
            flushBuffer();
          }
        }
    }
    xSemaphoreGive(_mutex);
  } else {
    esp3d_log_e("Mutex not taken");
  }
}

[rondlh]

Does this version solve your issue when not changing the timeout ? This version only peek what it available when callback is called so there is not infinite loop possible

Yes, that solves my issue at timeouts of 500ms, and the responsiveness is much faster too.
With this code the 500ms timeout becomes completely irrelevant, because copying the available serial data is very fast, it will never exit the while because of the timeout, it will always exit because the available serial data was handled.

You might as well use:
while (Serials[_serialIndex]->available())

Which will also guarantee the while loop will exit because copying the serial data is much faster than the serial data arrival speed.

If I understand the original code correctly, what it is trying to do is to not fragment a batch of serial lines (like M119, or M43). It wants to forward the lines as a whole. Even low timeout value of 5ms will achieve this, because the serial data comes in without much of a delay between the lines.

I had a look into the code, and checked what happens in flushBuffer() and in flushData. That all seems to be quite solid, I don't see any issues that can cause data to be written outside a allocated buffer or something. So I guess my issues is just that the while loop doesn't exit and that prevents other tasks from getting time to handle the things needed to connect the device.

Anyway, thanks again for you effort and support!

[luc-github]

I will review this today , using while (Serials[_serialIndex]->available()) may behave as existing code under overflowing data, between each check, the serial can be filled by another task, and so, you also may not exit the callback because of continuous incoming data
Indeed in test code SERIAL_COMMUNICATION_TIMEOUT is useless because now timeout is always reset, even no character is read

[luc-github]

Hi @rondlh please confirm the following code is working for you - I have simplified the callback

void ESP3DSerialService::receiveCb() {
  if (!started()) {
    return;
  }
  //take mutex
  if (xSemaphoreTake(_mutex, portMAX_DELAY)) {
    // Get expected len of data
    size_t count = Serials[_serialIndex]->available();
    
    //loop until each byte is handled
    while (count > 0) {
      int data = Serials[_serialIndex]->read();
      
      // If  read() failed we leave
      if (data == -1) {
        esp3d_log_e("Serial read failed unexpectedly");
        break;  // only break to release mutex
      }
      //take the char
      count--;
      _buffer[_buffer_size] = (uint8_t)data;
      //check what next step is
      if (esp3d_string::isRealTimeCommand(_buffer[_buffer_size])) {
        flushChar(_buffer[_buffer_size]);
        _buffer[_buffer_size] = '\0'; //remove realtime command from buffer
      } else {
        _buffer_size++;
        if (_buffer_size > ESP3D_SERIAL_BUFFER_SIZE || _buffer[_buffer_size - 1] == '\n') {
          flushBuffer();
        }
      }
    }
    //release mutex
    xSemaphoreGive(_mutex);
  } else {
    esp3d_log_e("Mutex not taken");
  }
}

[rondlh]

Hi @rondlh please confirm the following code is working for you - I have simplified the callback

Confirmed, the code works very well, even if I continuously send data to the serial port, and it is very responsive too.
I do not see any drawbacks in this change, only advantages.

[luc-github]

ok will merge it today , thank you for your feedback

[luc-github]

fix pushed 5501e78
Thank you again for the reporting and the tests