Arduino-esp32: LoadProhibited exception occurred at vsnprintf() in log_printf()

Created on 16 Jan 2019  路  8Comments  路  Source: espressif/arduino-esp32

Hardware:

Board: ESP32 Dev Module, Heltec WiFi kit 32
Core Installation version: 1.0.1 stable release
IDE name: Arduino IDE 1.8.6
Core debug level: Debug or higher
Partition Scheme: Default
Flash Frequency: 80Mhz, 40Mhz both
PSRAM enabled: no
Upload Speed: 921600
Computer OS: Windows 10

Description:

LoadProhibited exception occurred at vsnprintf() in log_printf() of esp32-hal-uart.c.
The code below is an excerpt of connection means using a so-called captive portal. After the first WiFi.begin() fails, change WiFi mode to AP_STA. Then activate SoftAP and try to connect from the cell phone to the AP of ESP32.

An exception occurs at the time of catching the event of the station (ie. from cell phone) connection request on the ESP32 side. The crash point is vsnprintf of log_printf(const char *format, ...) in esp32-hal-uart.c. It does not occur if the Core Debug Level is lowered below Info.

Sketch:

#include <WiFi.h>
#include <WebServer.h>
#include <DNSServer.h>

WebServer WebServer;
DNSServer DNSServer;
bool DNSActive = false;

void setup() {
  delay(1000);
  Serial.begin(115200);

  WiFi.softAPdisconnect(false);
  WiFi.enableAP(false);
  delay(100);
  WiFi.mode(WIFI_STA);
  delay(100);

  WiFi.begin();

  bool cs = waitForConnect(30000) == WL_CONNECTED;
  WebServer.begin();
  if (!cs) {
    WiFi.setAutoConnect(false);
    WiFi.disconnect(true, true);
    WiFi.mode(WIFI_AP_STA);
    delay(100);
    WiFi.softAP("esp32ap", "12345678", 1, 0);
    while (WiFi.softAPIP() == IPAddress(0, 0, 0, 0))
      delay(100);
    if (WiFi.softAPConfig(IPAddress(192, 168, 244, 1), IPAddress(192, 168, 244, 1), IPAddress(255, 255, 255, 0))) {
      Serial.printf("SoftAP %s\n", WiFi.softAPIP().toString().c_str());
      DNSServer.setErrorReplyCode(DNSReplyCode::NoError);
      DNSServer.start(53, "*", WiFi.softAPIP());
      Serial.println("DNS server started");
      DNSActive = true;
    }
    else
      Serial.println("WiFi.softAPConfig failed");
  }
}

void loop() {
  if (DNSActive) {
    DNSServer.processNextRequest();
  }
  WebServer.handleClient();
}

wl_status_t waitForConnect(unsigned long timeout) {
  wl_status_t wifiStatus;

  Serial.print("Connecting");
  unsigned long st = millis();
  while ((wifiStatus = WiFi.status()) != WL_CONNECTED) {
    if (timeout) {
      if (millis() - st > timeout)
        break;
    }
    Serial.print('.');
    delay(300);
  }
  Serial.printf("%s IP:%s\n", wifiStatus == WL_CONNECTED ? "established" : "time out", WiFi.localIP().toString().c_str());
  return wifiStatus;
}

Debug Messages:

rst:0xc (SW_CPU_RESET),boot:0x17 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0018,len:4
load:0x3fff001c,len:1100
load:0x40078000,len:10088
load:0x40080400,len:6392
entry 0x400806a4
[D][WiFiGeneric.cpp:342] _eventCallback(): Event: 0 - WIFI_READY
[D][WiFiGeneric.cpp:342] _eventCallback(): Event: 13 - AP_START
[D][WiFiGeneric.cpp:342] _eventCallback(): Event: 14 - AP_STOP
[D][WiFiGeneric.cpp:342] _eventCallback(): Event: 14 - AP_STOP
[E][WiFiSTA.cpp:211] begin(): connect failed!
Connecting.....................................................................................................time out IP:0.0.0.0
[D][WiFiGeneric.cpp:342] _eventCallback(): Event: 2 - STA_START
[D][WiFiGeneric.cpp:342] _eventCallback(): Event: 0 - WIFI_READY
[D][WiFiGeneric.cpp:342] _eventCallback(): Event: 13 - AP_START
[D][WiFiGeneric.cpp:342] _eventCallback(): Event: 13 - AP_START
SoftAP 192.168.244.1
DNS server started
E (185099) event: mismatch or invalid event, id=63
E (185099) event: default event handler failed!
Guru Meditation Error: Core  1 panic'ed (LoadProhibited). Exception was unhandled.
Core 1 register dump:
PC      : 0x400014dc  PS      : 0x00060430  A0      : 0x800e6138  A1      : 0x3ffb8f20  
A2      : 0x070518ff  A3      : 0x070518fb  A4      : 0x000000ff  A5      : 0x0000ff00  
A6      : 0x00ff0000  A7      : 0xff000000  A8      : 0x00000000  A9      : 0x00000000  
A10     : 0x00000000  A11     : 0x3ffb9122  A12     : 0x00000000  A13     : 0x00000000  
A14     : 0x60000000  A15     : 0x00000000  SAR     : 0x00000004  EXCCAUSE: 0x0000001c  
EXCVADDR: 0x070518ff  LBEG    : 0x400014fd  LEND    : 0x4000150d  LCOUNT  : 0xfffffffc  

Backtrace: 0x400014dc:0x3ffb8f20 0x400e6135:0x3ffb8f30 0x400ed666:0x3ffb9240 0x400ed69e:0x3ffb92d0 0x400d81a2:0x3ffb9310 0x400d2ba6:0x3ffb9370 0x400d2f01:0x3ffb9490 0x4008e729:0x3ffb94c0

Rebooting...

Decoding result of dump:

Decoding 11 results
0x400e6135: _svfprintf_r at /Users/ivan/e/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/stdio/../../../.././newlib/libc/stdio/vfprintf.c line 1529
0x400ed666: _vsnprintf_r at /Users/ivan/e/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/stdio/../../../.././newlib/libc/stdio/vsnprintf.c line 72
0x400ed69e: vsnprintf at /Users/ivan/e/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/stdio/../../../.././newlib/libc/stdio/vsnprintf.c line 41
0x400d81a2: log_printf at C:\Users\hiero\AppData\Local\Arduino15\packages\esp32\hardware\esp32\1.0.1\cores\esp32/esp32-hal-uart.c line 473
0x400d2ba6: WiFiGenericClass::_eventCallback(void*, system_event_t*) at C:\Users\hiero\AppData\Local\Arduino15\packages\esp32\hardware\esp32\1.0.1\libraries\WiFi\src/WiFiGeneric.cpp line 190
0x400d2f01: _network_event_task(void*) at C:\Users\hiero\AppData\Local\Arduino15\packages\esp32\hardware\esp32\1.0.1\libraries\WiFi\src/WiFiGeneric.cpp line 190
0x4008e729: vPortTaskWrapper at /Users/ficeto/Desktop/ESP32/ESP32/esp-idf-public/components/freertos/port.c line 355 (discriminator 1)

Preliminary diagnostics:

I had diagnosed the followings preliminary:

  • It is not occurrence with 1.0.0 stable release.
  • #701 : The problem was reproduced even by adding va_end which is missing.
  • #2283 : Here is part of the code that had swap softAP and softAPConfig, the problem still reproduces.
WiFi.setAutoConnect(false);
WiFi.disconnect(true, true);
WiFi.mode(WIFI_AP_STA);
delay(100);
if (WiFi.softAPConfig(IPAddress(192, 168, 244, 1), IPAddress(192, 168, 244, 1), IPAddress(255, 255, 255, 0))) {
  WiFi.softAP("esp32ap", "12345678", 1, 0);
  while (WiFi.softAPIP() == IPAddress(0, 0, 0, 0))
    delay(100);
  Serial.printf("SoftAP %s\n", WiFi.softAPIP().toString().c_str());
  DNSServer.setErrorReplyCode(DNSReplyCode::NoError);
  DNSServer.start(53, "*", WiFi.softAPIP());
  Serial.println("DNS server started");
  DNSActive = true;
}
picture Hieromon

Most helpful comment

I also confirmed the esp-idf. That is undefined. But for the debug log, I think your amendment is reasonable.

picture Hieromon on 16 Jan 2019
👍3

All 8 comments

I traced it with a slight modification of log_printf() and got the result the below.
It dumps format string and arguments to log_printf(), parameter#5 as a pointer.

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:1
load:0x3fff0018,len:4
load:0x3fff001c,len:1100
load:0x40078000,len:10088
load:0x40080400,len:6380
entry 0x400806a4
log_printf: [D][%s:%u] %s(): Event: %d - %s
args: WiFiGeneric.cpp, 342, _eventCallback, 0, 0x3f4008ee
log_printf: [D][%s:%u] %s(): Event: %d - %s
args: WiFiGeneric.cpp, 342, _eventCallback, 13, 0x3f4009a7
[D][WiFiGeneric.cpp:342] _eventCallback(): Event: 13 - AP_START
log_printf: [D][%s:%u] %s(): Event: %d - %s
args: WiFiGeneric.cpp, 342, _eventCallback, 13, 0x3f4009a7
[D][WiFiGeneric.cpp:342] _eventCallback(): Event: 13 - AP_START
[D][WiFiGeneric.cpp:342] _eventCallback(): Event: 0 - WIFI_READY
log_printf: [D][%s:%u] %s(): Event: %d - %s
args: WiFiGeneric.cpp, 342, _eventCallback, 14, 0x3f4009b0
[D][WiFiGeneric.cpp:342] _eventCallback(): Event: 14 - AP_STOP
log_printf: [E][%s:%u] %s(): connect failed!
args: WiFiSTA.cpp, 211, begin, 1073447000, 0x40140fb4
[E][WiFiSTA.cpp:211] begin(): connect failed!
....................................................................................................time out IP:0.0.0.0
log_printf: [D][%s:%u] %s(): Event: %d - %s
args: WiFiGeneric.cpp, log_printf: [D][%s:%u] %s(): Event: %d - %s
args: WiFiGeneric.cpp, 342, _eventCallback, 2, 0x3f400903
[D][WiFiGeneric.cpp:342] _eventCallback(): Event: 2 - STA_START
log_printf: [D][%s:%u] %s(): Event: %d - %s
args: WiFiGeneric.cpp, 342, _eventCallback, 2, 0x3f400903
[D][WiFiGeneric.cpp:342] _eventCallback(): Event: 2 - STA_START
342, _eventCallback, 0, 0x3f4008ee
[D][WiFiGeneric.cpp:342] _eventCallback(): Event: 0 - WIFI_READY
log_printf: [D][%s:%u] %s(): Event: %d - %s
args: WiFiGeneric.cpp, 342, _eventCallback, 13, 0x3f4009a7
[D][WiFiGeneric.cpp:342] _eventCallback(): Event: 13 - AP_START
SoftAP 192.168.244.1
DNS server started
E (140827) event: mismatch or invalid event, id=63
E (140827) event: default event handler failed!
log_printf: [D][%s:%u] %s(): Event: %d - %s
args: WiFiGeneric.cpp, 342, _eventCallback, 63, 0x070518ff
Guru Meditation Error: Core  1 panic'ed (LoadProhibited). Exception was unhandled.
Core 1 register dump:
PC      : 0x400014dc  PS      : 0x00060e30  A0      : 0x800e61cc  A1      : 0x3ffb8f10  
A2      : 0x070518ff  A3      : 0x070518fb  A4      : 0x000000ff  A5      : 0x0000ff00  
A6      : 0x00ff0000  A7      : 0xff000000  A8      : 0x00000000  A9      : 0x00000000  
A10     : 0x00000000  A11     : 0x3ffb9112  A12     : 0x00000000  A13     : 0x00000000  
A14     : 0x60000000  A15     : 0x00000000  SAR     : 0x00000004  EXCCAUSE: 0x0000001c  
EXCVADDR: 0x070518ff  LBEG    : 0x400014fd  LEND    : 0x4000150d  LCOUNT  : 0xfffffffc

As parameter#5 for the format [D][%s:%u] %s(): Event: %d - %s, is the address 0x070518ff correct? When the invalid event occurs and the default handler fails, parameter#5 seems to be lost. It is both out of Data and Instruction area.
In WiFiGeneric.cpp, _eventCallback has passed the element of system_event_names array to log_d, but id<63> occurred.
https://github.com/espressif/arduino-esp32/blob/6cf307dbd1cfc46d489609cf675fab2806e6054d/libraries/WiFi/src/WiFiGeneric.cpp#L334

Hieromon picture Hieromon on 16 Jan 2019

param 5 should be an error text string, likely since there is no match for the error string it is returning an invalid pointer resulting in the error you are seeing. Most likely a validity check is going to be needed in the event handler to handle the invalid type, maybe something like this:

if(event->event_id > sizeof(system_event_names)) {
  log_d("Event: %d - unknown", event->event_id);
} else {  
  log_d("Event: %d - %s", event->event_id, system_event_names[event->event_id]);
}

here: https://github.com/espressif/arduino-esp32/blob/master/libraries/WiFi/src/WiFiGeneric.cpp#L342

this is probably not 100% right, it likely would be better to have a method with a switch statement to return a string object based on the event ID names but this is what is there now.

atanisoft picture atanisoft on 16 Jan 2019

@atanisoft So, the event handling of WiFiGeneric.cpp is inadequate. In reality can occur. Well, I have not yet examined what is.

Hieromon picture Hieromon on 16 Jan 2019

yup, i don't know what event 63 means or could be but certainly there are some unknown codes being sent in and there certainly aren't 63 unique values in that array today, it would make more sense to use a switch and have known event IDs in it etc...

atanisoft picture atanisoft on 16 Jan 2019

63 doesn't even seem to be a valid error code either: https://github.com/espressif/esp-idf/blob/master/components/esp32/include/esp_wifi_types.h#L66-L96

not sure what to make of that error now, but with some errors over 200 in the list we would need to do something different here for sure. @me-no-dev thoughts?

atanisoft picture atanisoft on 16 Jan 2019

I also confirmed the esp-idf. That is undefined. But for the debug log, I think your amendment is reasonable.

Hieromon picture Hieromon on 16 Jan 2019
👍3

2340 tested, fix confirmed for me.

chinswain picture chinswain on 17 Jan 2019

I confirmed the fix. Thanks.
https://github.com/espressif/arduino-esp32/commit/45fa0f829449419aee83d61f967ca32450e63527

Hieromon picture Hieromon on 22 Jan 2019
Was this page helpful?
0 / 5 - 0 ratings

Related issues

danthegoodman1 picture danthegoodman1  路  100Comments
dsyleixa picture dsyleixa  路  65Comments
JohnGEyles picture JohnGEyles  路  53Comments
dbachko picture dbachko  路  84Comments
PhilColbert picture PhilColbert  路  125Comments