Closed mathieucarbou closed 8 months ago
bblanchon
commented
8 months ago Hi @mathieucarbou,
This looks like a corrupted JsonDocument.
Are you sure the received reference is pointing to a valid object?
The stack trace shows a generateLayoutJSON() called from a lambda, called by a callback handler.
None of this is visible in the code you shared.
Could you reproduce this bug in an MCVE?
Best regards, Benoit
mathieucarbou
commented
8 months ago generateLayoutJSON
Hello,
Yes that's what I am thinking: I discovered yesterday that the library I use is not thread safe and is calling this generateLayoutJSON method that is populating a json document both from the async_http task and the loop task. I am digging into the issue and close this one. thanks!
mathieucarbou
commented
8 months ago @bblanchon : I have to re-open it... I have removed any potential concurrent access: now, the generateLayout method is only called once from the async_http task (websocket handler) and nowhere else.. Also, the json document reads data that is initialised once, stays as references in private fields in a static class, and this data is not modified concrurently.
While the json document is building, I have this error again, and constantly:
D 5142 YaSolR-I/O (1) HA-DISCO Publishing HA Discovery configuration for sensor output2_state...
D 5186 YaSolR-I/O (1) HA-DISCO Publishing HA Discovery configuration for sensor output2_routed_power...
D 5290 YaSolR-I/O (1) HA Published in 2176 ms
W 5293 YaSolR-I/O (1) I/O Abnormal loop duration: 2179 ms
D 5434 loopTask (1) DISPLAY Updated in 49 ms
[ 6805][W][AsyncTCP.cpp:950] _poll(): rx timeout 4
D 7610 YaSolR-I/O (1) I/O Published in 2262 ms
W 7613 YaSolR-I/O (1) I/O Abnormal loop duration: 2265 ms
T 8130 async_tcp (1) ESP-DASH client=1, measureJson=612
assert failed: ArduinoJson::V701PB2::detail::VariantSlot* ArduinoJson::V701PB2::detail::VariantPoolList::getSlot(ArduinoJson::V701PB2::detail::SlotId) const VariantPoolList.hpp:98 (poolIndex < count_
Backtrace: 0x400838e5:0x3ffecc70 0x4008dbcd:0x3ffecc90 0x40093719:0x3ffeccb0 0x400dd150:0x3ffecde0 0x40121d5b:0x3ffece80 0x401240ad:0x3ffecea0 0x40126636:0x3ffed5b0 0x40126b31:0x3ffed630 0x401c3bf1:0x3ffed660 0x401c3c16:0x3ffed6b0 0x401c4fd9:0x3ffed6e0 0x401c50b5:0x3ffed720 0x401c0a1f:0x3ffed740 0x401c0a6e:0x3ffed770 0x401c0ab1:0x3ffed790 0x401c0c8d:0x3ffed7b0 0x401c0d09:0x3ffed7d0
#0 0x400838e5:0x3ffecc70 in panic_abort at /Users/ficeto/Desktop/ESP32/ESP32S2/esp-idf-public/components/esp_system/panic.c:408
#1 0x4008dbcd:0x3ffecc90 in esp_system_abort at /Users/ficeto/Desktop/ESP32/ESP32S2/esp-idf-public/components/esp_system/esp_system.c:137
#2 0x40093719:0x3ffeccb0 in __assert_func at /Users/ficeto/Desktop/ESP32/ESP32S2/esp-idf-public/components/newlib/assert.c:85
#3 0x400dd150:0x3ffecde0 in ArduinoJson::V701PB2::detail::VariantPoolList::getSlot(unsigned short) const at .pio/libdeps/pro-esp32-debug/ArduinoJson/src/ArduinoJson/Memory/VariantPoolList.hpp:98
(inlined by) ArduinoJson::V701PB2::detail::VariantPoolList::allocFromFreeList() at .pio/libdeps/pro-esp32-debug/ArduinoJson/src/ArduinoJson/Memory/VariantPoolImpl.hpp:71
(inlined by) ArduinoJson::V701PB2::detail::VariantPoolList::allocSlot(ArduinoJson::V701PB2::Allocator*) at .pio/libdeps/pro-esp32-debug/ArduinoJson/src/ArduinoJson/Memory/VariantPoolList.hpp:73
(inlined by) ArduinoJson::V701PB2::detail::ResourceManager::allocSlot() at .pio/libdeps/pro-esp32-debug/ArduinoJson/src/ArduinoJson/Memory/ResourceManager.hpp:53
(inlined by) ArduinoJson::V701PB2::detail::CollectionData::addSlot(ArduinoJson::V701PB2::detail::ResourceManager*) at .pio/libdeps/pro-esp32-debug/ArduinoJson/src/ArduinoJson/Collection/CollectionImpl.hpp:52
(inlined by) ArduinoJson::V701PB2::detail::VariantData* ArduinoJson::V701PB2::detail::ObjectData::addMember<ArduinoJson::V701PB2::detail::StaticStringAdapter>(ArduinoJson::V701PB2::detail::StaticStringAdapter, ArduinoJson::V701PB2::detail::ResourceManager*) at .pio/libdeps/pro-esp32-debug/ArduinoJson/src/ArduinoJson/Object/ObjectData.hpp:27
(inlined by) ArduinoJson::V701PB2::detail::VariantData* ArduinoJson::V701PB2::detail::ObjectData::getOrAddMember<ArduinoJson::V701PB2::detail::StaticStringAdapter>(ArduinoJson::V701PB2::detail::StaticStringAdapter, ArduinoJson::V701PB2::detail::ResourceManager*) at .pio/libdeps/pro-esp32-debug/ArduinoJson/src/ArduinoJson/Object/ObjectImpl.hpp:24
#4 0x40121d5b:0x3ffece80 in ArduinoJson::V701PB2::detail::VariantData* ArduinoJson::V701PB2::detail::VariantData::getOrAddMember<ArduinoJson::V701PB2::detail::StaticStringAdapter>(ArduinoJson::V701PB2::detail::StaticStringAdapter, ArduinoJson::V701PB2::detail::ResourceManager*) at .pio/libdeps/pro-esp32-debug/ArduinoJson/src/ArduinoJson/Variant/VariantData.hpp:226
#5 0x401240ad:0x3ffecea0 in ArduinoJson::V701PB2::detail::MemberProxy<ArduinoJson::V701PB2::JsonObject, char const*>::getOrCreateData() const at .pio/libdeps/pro-esp32-debug/ArduinoJson/src/ArduinoJson/Object/MemberProxy.hpp:59
(inlined by) ArduinoJson::V701PB2::detail::VariantData* ArduinoJson::V701PB2::detail::VariantAttorney::getOrCreateData<ArduinoJson::V701PB2::detail::MemberProxy<ArduinoJson::V701PB2::JsonObject, char const*> const>(ArduinoJson::V701PB2::detail::MemberProxy<ArduinoJson::V701PB2::JsonObject, char const*> const&) at .pio/libdeps/pro-esp32-debug/ArduinoJson/src/ArduinoJson/Variant/VariantAttorney.hpp:32
(inlined by) ArduinoJson::V701PB2::detail::VariantRefBase<ArduinoJson::V701PB2::detail::MemberProxy<ArduinoJson::V701PB2::JsonObject, char const*> >::getOrCreateData() const at .pio/libdeps/pro-esp32-debug/ArduinoJson/src/ArduinoJson/Variant/VariantRefBase.hpp:268
(inlined by) ArduinoJson::V701PB2::detail::VariantRefBase<ArduinoJson::V701PB2::detail::MemberProxy<ArduinoJson::V701PB2::JsonObject, char const*> >::getOrCreateVariant() const at .pio/libdeps/pro-esp32-debug/ArduinoJson/src/ArduinoJson/Variant/VariantRefBaseImpl.hpp:100
(inlined by) bool ArduinoJson::V701PB2::detail::VariantRefBase<ArduinoJson::V701PB2::detail::MemberProxy<ArduinoJson::V701PB2::JsonObject, char const*> >::set<char const>(char const*) const at .pio/libdeps/pro-esp32-debug/ArduinoJson/src/ArduinoJson/Variant/VariantRefBaseImpl.hpp:144
(inlined by) ArduinoJson::V701PB2::detail::MemberProxy<ArduinoJson::V701PB2::JsonObject, char const*>& ArduinoJson::V701PB2::detail::MemberProxy<ArduinoJson::V701PB2::JsonObject, char const*>::operator=<char const>(char const*) at .pio/libdeps/pro-esp32-debug/ArduinoJson/src/ArduinoJson/Object/MemberProxy.hpp:39
(inlined by) ESPDash::generateLayoutJSON(AsyncWebSocketClient*, bool, Card*) at lib/ESPDASHPro/src/ESPDashPro.cpp:334
#6 0x40126636:0x3ffed5b0 in ESPDash::ESPDash(AsyncWebServer*, char const*, bool)::{lambda(AsyncWebSocket*, AsyncWebSocketClient*, AwsEventType, void*, unsigned char*, unsigned int)#3}::operator()(AsyncWebSocket*, AsyncWebSocketClient*, AwsEventType, void*, unsigned char*, unsigned int) const at lib/ESPDASHPro/src/ESPDashPro.cpp:91
#7 0x40126b31:0x3ffed630 in std::_Function_handler<void (AsyncWebSocket*, AsyncWebSocketClient*, AwsEventType, void*, unsigned char*, unsigned int), ESPDash::ESPDash(AsyncWebServer*, char const*, bool)::{lambda(AsyncWebSocket*, AsyncWebSocketClient*, AwsEventType, void*, unsigned char*, unsigned int)#3}>::_M_invoke(std::_Any_data const&, AsyncWebSocket*&&, AsyncWebSocketClient*&&, AwsEventType&&, void*&&, unsigned char*&&, unsigned int&&) at /Users/mat/.platformio/packages/toolchain-xtensa-esp32@8.4.0+2021r2-patch5/xtensa-esp32-elf/include/c++/8.4.0/bits/std_function.h:297
#8 0x401c3bf1:0x3ffed660 in std::function<void (AsyncWebSocket*, AsyncWebSocketClient*, AwsEventType, void*, unsigned char*, unsigned int)>::operator()(AsyncWebSocket*, AsyncWebSocketClient*, AwsEventType, void*, unsigned char*, unsigned int) const at /Users/mat/.platformio/packages/toolchain-xtensa-esp32@8.4.0+2021r2-patch5/xtensa-esp32-elf/include/c++/8.4.0/bits/std_function.h:687
#9 0x401c3c16:0x3ffed6b0 in AsyncWebSocket::_handleEvent(AsyncWebSocketClient*, AwsEventType, void*, unsigned char*, unsigned int) at .pio/libdeps/pro-esp32-debug/ESP Async WebServer/src/AsyncWebSocket.cpp:771
#10 0x401c4fd9:0x3ffed6e0 in AsyncWebSocketClient::_onData(void*, unsigned int) at .pio/libdeps/pro-esp32-debug/ESP Async WebServer/src/AsyncWebSocket.cpp:563
#11 0x401c50b5:0x3ffed720 in std::_Function_handler<void (void*, AsyncClient*, void*, unsigned int), AsyncWebSocketClient::AsyncWebSocketClient(AsyncWebServerRequest*, AsyncWebSocket*)::{lambda(void*, AsyncClient*, void*, unsigned int)#5}>::_M_invoke(std::_Any_data const&, void*&&, AsyncClient*&&, std::_Any_data const&, unsigned int&&) at .pio/libdeps/pro-esp32-debug/ESP Async WebServer/src/AsyncWebSocket.cpp:272
(inlined by) _M_invoke at /Users/mat/.platformio/packages/toolchain-xtensa-esp32@8.4.0+2021r2-patch5/xtensa-esp32-elf/include/c++/8.4.0/bits/std_function.h:297
#12 0x401c0a1f:0x3ffed740 in std::function<void (void*, AsyncClient*, void*, unsigned int)>::operator()(void*, AsyncClient*, void*, unsigned int) const at /Users/mat/.platformio/packages/toolchain-xtensa-esp32@8.4.0+2021r2-patch5/xtensa-esp32-elf/include/c++/8.4.0/bits/std_function.h:687
#13 0x401c0a6e:0x3ffed770 in AsyncClient::_recv(tcp_pcb*, pbuf*, signed char) at .pio/libdeps/pro-esp32-debug/AsyncTCP/src/AsyncTCP.cpp:915
#14 0x401c0ab1:0x3ffed790 in AsyncClient::_s_recv(void*, tcp_pcb*, pbuf*, signed char) at .pio/libdeps/pro-esp32-debug/AsyncTCP/src/AsyncTCP.cpp:1191
#15 0x401c0c8d:0x3ffed7b0 in _handle_async_event(lwip_event_packet_t*) at .pio/libdeps/pro-esp32-debug/AsyncTCP/src/AsyncTCP.cpp:159
#16 0x401c0d09:0x3ffed7d0 in _async_service_task(void*) at .pio/libdeps/pro-esp32-debug/AsyncTCP/src/AsyncTCP.cpp:194
ELF file SHA256: 51ad2d96511c2487
E (8608) esp_core_dump_flash: Core dump flash config is corrupted! CRC=0x7bd5c66f instead of 0x0
Rebooting...
ets Jul 29 2019 12:21:46
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:0x3fff0030,len:1184
load:0x40078000,len:13232
load:0x40080400,len:3028
entry 0x400805e4
E (732) esp_core_dump_flash: No core du����ѥѥ���found!
E (732) esp_core_dump_flash: No core dump partition found!
I 35 loopTask (1) YASOLR Booting YaSolR Pro main_a96ee3d8_modified...
I 36 loopTask (1) SYSTEM Initializing File System...It also also fails at the place:
(inlined by) ESPDash::generateLayoutJSON(AsyncWebSocketClient*, bool, Card*) at lib/ESPDASHPro/src/ESPDashPro.cpp:334This line matches doc["command"] = changes_only ? "update:components" : "update:layout:next"; here:
JsonObject doc = root.to<JsonObject>();
doc["command"] = changes_only ? "update:components" : "update:layout:next";
for (int i = 0; i < cards.Size(); i++) {So it is like a document becomes unusable after being cleared. If I do not use .to<> but .clear() instead, I have the same behaviour.
We can see in the logs above that the first call to send() works, then the document is cleared for re-use and it crashes.
Here is part of the code:
// generates the layout JSON string to the frontend
void ESPDash::generateLayoutJSON(AsyncWebSocketClient* client, bool changes_only, Card* onlyCard) {
#if ARDUINOJSON_VERSION_MAJOR == 6
DynamicJsonDocument root(DASH_JSON_SIZE);
#else
JsonDocument root;
#endif
// preparing layout
{
JsonObject doc = root.to<JsonObject>();
if (!changes_only) {
doc["command"] = "update:layout:begin";
// OTHER DOC SETTERS
} else {
doc["command"] = "update:components";
}
// Generate Tab JSON
for (int i = 0; i < tabs.Size(); i++) {
// [...]
doc["tabs"][i]["id"] = t->_id;
// [...]
// OTHER DOC SETTERS
}
if (!changes_only || doc["tabs"].as<JsonArray>().size() > 0) {
send(client, doc);
}
}
// Generate JSON for all Cards
{
JsonObject doc = root.to<JsonObject>();
doc["command"] = changes_only ? "update:components" : "update:layout:next";
for (int i = 0; i < cards.Size(); i++) {
// [...]
// Generate JSON
#if ARDUINOJSON_VERSION_MAJOR == 6
JsonObject obj = doc["cards"].createNestedObject();
#else
JsonObject obj = doc["cards"].add<JsonObject>();
#endif
generateComponentJSON(obj, c, changes_only);
if (overflowed(root)) {
doc["cards"].as<JsonArray>().remove(doc["cards"].as<JsonArray>().size() - 1);
send(client, doc);
doc = root.to<JsonObject>();
doc["command"] = changes_only ? "update:components" : "update:layout:next";
i--;
continue;
}
// [...]
}
if (doc["cards"].as<JsonArray>().size() > 0)
send(client, doc);
}
// Generate JSON for all Charts
{
JsonObject doc = root.to<JsonObject>();
doc["command"] = changes_only ? "update:components" : "update:layout:next";
for (int i = 0; i < charts.Size(); i++) {
// [...]
// Generate JSON
#if ARDUINOJSON_VERSION_MAJOR == 7
JsonObject obj = doc["charts"].add<JsonObject>();
#else
JsonObject obj = doc["charts"].createNestedObject();
#endif
generateComponentJSON(obj, c, changes_only);
if (overflowed(root)) {
doc["charts"].as<JsonArray>().remove(doc["charts"].as<JsonArray>().size() - 1);
send(client, doc);
doc = root.to<JsonObject>();
doc["command"] = changes_only ? "update:components" : "update:layout:next";
i--;
continue;
}
// [...]
}
if (doc["charts"].as<JsonArray>().size() > 0)
send(client, doc);
}
// Generate JSON for all Statistics
{
JsonObject doc = root.to<JsonObject>();
doc["command"] = changes_only ? "update:components" : "update:layout:next";
int idx = 0;
// Check if default statistics are needed
if (default_stats_enabled) {
if (!changes_only) {
// OTHER DOC SETTERS
}
// Loop through user defined stats
for (int i = 0; i < statistics.Size(); i++, idx++) {
// [...]
// OTHER DOC SETTERS
if (overflowed(root)) {
doc["stats"].as<JsonArray>().remove(idx);
send(client, doc);
doc = root.to<JsonObject>();
doc["command"] = changes_only ? "update:components" : "update:layout:next";
i--;
idx = 0;
continue;
}
// Clear change flags
if (changes_only) {
s->_changed = false;
}
}
if (doc["stats"].as<JsonArray>().size() > 0)
send(client, doc);
}
}
void ESPDash::send(AsyncWebSocketClient* client, JsonObject& doc) {
const size_t len = measureJson(doc);
auto buffer = std::make_shared<std::vector<uint8_t>>(len);
if (!buffer) {
doc.clear();
return;
}
serializeJson(doc, buffer->data(), len);
#ifdef DASH_DEBUG
Serial.printf("T %12u %-10.10s (%u) ESP-DASH client=%u, measureJson=%u\r\n", static_cast<uint32_t>(esp_timer_get_time() >> 10), pcTaskGetName(NULL), xPortGetCoreID(), (client == nullptr ? -1 : client->id()), len);
#endif
if (client != nullptr) {
client->text(buffer);
} else {
_ws->textAll(buffer);
}
doc.clear();
}
bool ESPDash::overflowed(JsonDocument& json) {
return json.overflowed() || measureJson(json.as<JsonObject>()) > DASH_JSON_SIZE;
}Ok so there is definitely something wrong with reusing a Json doc after a clear().
I've implemented a new version which is creating a new JsonDocument each time, and it works.
mathieucarbou
commented
8 months ago We have a big internet outage here but as soon as I can, yes.
mathieucarbou
commented
8 months ago Here is a simple .ino file to reproduce:
#include <ArduinoJson.h>
void fill(JsonObject &obj) {
obj["foo-bar-baz"] = "foo-bar-baz-foo-bar-baz";
}
void send(JsonObject &obj) {
serializeJson(obj, Serial);
Serial.println("");
obj.clear();
}
void setup() {
Serial.begin(115200);
JsonDocument doc;
{
JsonObject obj = doc.to<JsonObject>();
obj["command"] = "update:components";
obj["tabs"][0]["id"] = "0";
send(obj);
}
{
JsonObject obj = doc.to<JsonObject>();
obj["command"] = "update:components";
JsonObject card = doc["cards"].add<JsonObject>();
fill(card);
send(obj);
}
}
void loop() { }Please note that if I comment out the obj.clear() line, it works:
void send(JsonObject &obj) {
serializeJson(obj, Serial);
Serial.println("");
//obj.clear();
}logs:
23:31:55.567 -> A6 : 0x00000000 A7 : 0x00000001 A8 : 0x800d142c A9 : 0x3ffc5040
23:31:55.599 -> A10 : 0x00000010 A11 : 0x00000010 A12 : 0x0000ffff A13 : 0x0000ffff
23:31:55.599 -> A14 : 0x0000ffff A15 : 0xff000000 SAR : 0x00000020 EXCCAUSE: 0x0000001c
23:31:55.599 -> EXCVADDR: 0x0000001a LBEG : 0x400862d9 LEND : 0x400862e9 LCOUNT : 0xffffffff
23:31:55.599 ->
23:31:55.599 ->
23:31:55.599 -> Backtrace: 0x400d1429:0x3ffc5060 0x400d198e:0x3ffc50a0 0x400d19d3:0x3ffc50e0 0x400d1f22:0x3ffc5100 0x400d301a:0x3ffc51b0
23:31:55.633 ->
23:31:55.633 ->
23:31:55.633 ->
23:31:55.633 ->
23:31:55.633 -> ELF file SHA256: 10fa9a3b88ba00e6
23:31:55.633 ->
23:31:55.829 -> Rebooting...What is the recommandation for such usage: use only one JsonDocument and scope the construction of inner batches to send through websocket, or constructing a completely new JsonDocument for each batch, scoped by brackets ?
My assumption was that destroying and creating a new JsonDocument each time would be slower, so that is why I've tried to reuse it with clear() and .to() calls.
bblanchon
commented
8 months ago Thank you very much for this code. :heart: It's now fixed in the main branch, and I'll publish a new revision soon.
What is the recommandation for such usage: use only one JsonDocument and scope the construction of inner batches to send through websocket, or constructing a completely new JsonDocument for each batch, scoped by brackets ?
I recommend short lifetimes to release memory as soon as possible and reduce the cognitive load.
In your case, this would mean creating a new JsonDocument for each batch.
My assumption was that destroying and creating a new JsonDocument each time would be slower, so that is why I've tried to reuse it with clear() and .to() calls.
Calling JsonDocument::clear() and destructing a JsonDocument are roughly the same; I don't expect any measurable difference.
Choose the one that makes the code easier to read and reason about.
mathieucarbou
commented
8 months ago Thanks for the advices, and glad I was able to help :-)
bblanchon
commented
8 months ago The fix was published in ArduinoJson 7.0.2.
I cannot use the the Arduino Json Troubleshooter since the issue happens when building a json document, when allocating memory.
I do not use any custom allocator.
Board is the standard ESP32 NodePCU Dev Kit from AZ-Delivery.
I have no idea what to do or how to troubleshoot this...
How I am using the JsonDocument:
Stack trace: