WARP1: Core 1 panic'ed

[poohnet]

Hallo zusammen,

vorab erstmal ein Lob: Der Umzug des WARP-Repositories in esp32-firmware ist super, damit lässt sich die komplette Buildumgebung ja nun tatsächlich mit wenigen Befehlen aufsetzen. 🙂

Jetzt das ABER: Leider funktioniert die damit erstellte Firmware nicht mehr - zumindest nicht auf meinem WARP1. Nach dem Flashen war der WARP-Charger reproduzierbar nicht mehr per WLAN erreichbar, sodass ich den ESP32 ausbauen und mit Hilfe von Brickv zurücksetzen musste.

Mit Hilfe des Serial Monitors konnte ich erkennen, dass es anscheinend ein Problem mit dem SPIFFS gibt, das in Folge dann zu einem "Core 1 panic" führt:

ets Jul 29 2019 12:21:46

rst:0xc (SW_CPU_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:2
load:0x3fff0018,len:4
load:0x3fff001c,len:976
ho 0 tail 12 room 4
load:0x40078000,len:10124
load:0x40080400,len:5828
entry 0x400806a8
15              **** TINKERFORGE WARP CHARGER V1.3.0-61a119ca ****
16                   278K RAM SYSTEM   234296 HEAP BYTES FREE
17          READY.
Checking if spiffs is mountable as SPIFFS. Please ignore following SPIFFS errors
E (27) SPIFFS: mount failed, -10025
Checking if coredump is mountable as LittleFS. Please ignore following LittleFS errors
../components/esp_littlefs/src/littlefs/lfs.c:1071:error: Corrupted dir pair at {0x0, 0x1}
E (43) esp_littlefs: mount failed,  (-84)
E (46) esp_littlefs: Failed to initialize LittleFS
E (51) esp_littlefs: Partition was never registered.
Checking if spiffs is mountable as LittleFS. Please ignore following LittleFS errors
90          Mounted configuration partition. 8192 of 3538944 bytes (0.2 %) used
136         WARP Charger SPIFFS version 1.3.0-617bc859
623         mDNS responder started
Guru Meditation Error: Core  1 panic'ed (LoadProhibited). Exception was unhandled.

Core  1 register dump:
PC      : 0x4008a8e4  PS      : 0x00060830  A0      : 0x80089c1d  A1      : 0x3ffb1f90  
A2      : 0x00006465  A3      : 0x00006461  A4      : 0x000000ff  A5      : 0x0000ff00
A6      : 0x00ff0000  A7      : 0xff000000  A8      : 0x8008f20c  A9      : 0x3ffb1f70  
A10     : 0x00000003  A11     : 0x00060823  A12     : 0x00060820  A13     : 0x00000000
A14     : 0x00001004  A15     : 0x3ffb6c68  SAR     : 0x00000008  EXCCAUSE: 0x0000001c  
EXCVADDR: 0x00006465  LBEG    : 0x400894b9  LEND    : 0x400894db  LCOUNT  : 0xffffffff


Backtrace:0x4008a8e1:0x3ffb1f900x40089c1a:0x3ffb1fa0 0x40089c09:0x3ffb1fc0 0x40137329:0x3ffb1fe0 0x401383ec:0x3ffb2000 0x40138be3:0x3ffb2040 0x400f2e00:0x3ffb2090 0x400e0f11:0x3ffb21e0 0x4010627e:0x3ffb2820 




ELF file SHA256: 0000000000000000

Rebooting...

 

Zuerst dachte ich noch an einen Programmierfehler meinerseits, das Problem lässt sich aber auch mit dem unveränderten Sourcecode reproduzieren. Verwendet man stattdessen die "alte" Buildumgebung (tag 1.3.0 im warp-charger Repository), dann funktioniert alles einwandfrei.

Habt ihr vielleicht eine Idee, woran das liegen könnte?

Besten Dank und Gruß
Thomas

bearbeitet November 27, 2021 at 18:10 von poohnet

[rtrbt]

Moin Thomas,

Das sieht im ersten Moment in der Tat so aus, als wäre es ein SPIFFS-Problem, ist es aber vermutlich nicht. Die verwirrenden Meldungen kommen daher, dass wir in letzter Zeit von SPIFFS auf LittleFS umgestellt haben, weil das schneller und vorallem robuster ist. Damit dann bei einem Update von einer SPIFFS auf eine LittleFS-Firmware nicht die Konfiguration verloren geht, macht die (neue) Firmware einen Migrationsschritt, der unter anderem involviert, dass die zunächst geprüft wird, ob die Konfigurationspartition eine SPIFFS-Partition ist, und wenn ja, wird die Migration ausgeführt.

Diese Prüfung führt aber noch dazu, dass Meldungen wie

Quote

E (27) SPIFFS: mount failed, -10025

angezeigt werden. Das aufzuhübschen ist einer der nächsten Schritte, ich hatte dann als Schnellschuss erstmal die Meldung davor eingebaut:

Quote

Checking if spiffs is mountable as SPIFFS. Please ignore following SPIFFS errors

D.h. du kannst das ignorieren. Es hatte erstmal nicht die höchste Priorität, die verwirrenden Meldungen loszuwerden, da man sie ja nur auf der seriellen Konsole sieht.

Quote

Checking if spiffs is mountable as LittleFS. Please ignore following LittleFS errors
90          Mounted configuration partition. 8192 of 3538944 bytes (0.2 %) used

Diese Kombination aus Logmeldungen sagt dann übrigens, dass alles soweit okay ist, die Konfigurationspartition ist ein LittleFS und lies sich erfolgreich mounten.

 

Zu deinem eigentlichen Problem: Da das Mounten klappt, steckt der Fehler wo anders. Am besten decodierst du den Backtrace, der ausgegeben wird, dann siehst du, in welchem Codestück der ESP sich aufhängt: Dazu brauchst du die zugehörige .elf-Datei zu der .bin-Datei, die du geflasht hast (die sollte im build-Verzeichnis liegen und die selbe Versionsnummer haben. Also zu warp2_firmware_1_3_0-61a119ca.bin z.B. die warp2_firmware_1_3_0-61a119ca.elf.). Das Dekodieren kannst du mit xtensa-esp32-elf-addr2line auf der Kommandozeile machen machen, das liegt im Platformio-Ordner (https://docs.platformio.org/en/latest/projectconf/section_platformio.html#directory-options) unter packages/toolchain-xtensa-esp32/bin/

xtensa-esp32-elf-addr2line -pfiaC -e /pfad/zur/warp2_firmware_1_3_0-61a119ca.elf 0x4008a8e1:0x3ffb1f900x40089c1a:0x3ffb1fa0 0x40089c09:0x3ffb1fc0 0x40137329:0x3ffb1fe0 0x401383ec:0x3ffb2000 0x40138be3:0x3ffb2040 0x400f2e00:0x3ffb2090 0x400e0f11:0x3ffb21e0 0x4010627e:0x3ffb2820 

Sollte dir dann einen sinnvollen Backtrace ausgeben, mit Dateinamen und Zeilennummern. Den kannst du gerne hier posten, dann werfe ich auch mal einen Blick darauf, vorallem wenn das Problem nicht in deinem Code auftritt.

Grüße,
Erik

[poohnet]

Moin Erik,

besten Dank für die schnelle Rückmeldung, das werde ich heute Abend mal ausprobieren.

Gestern habe ich übrigens noch herausgefunden, dass der Crash auftritt, sobald man MQTT aktiviert. Vielleicht hilft das vorab schon mal weiter...

Gruß Thomas

[photron]

On 11/27/2021 at 3:25 PM, poohnet said:

Zuerst dachte ich noch an einen Programmierfehler meinerseits, das Problem lässt sich aber auch mit dem unveränderten Sourcecode reproduzieren. Verwendet man stattdessen die "alte" Buildumgebung (tag 1.3.0 im warp-charger Repository), dann funktioniert alles einwandfrei.

Auf welchem Commit in esp32-firmware Repository arbeitest du denn?

 

2 hours ago, poohnet said:

Gestern habe ich übrigens noch herausgefunden, dass der Crash auftritt, sobald man MQTT aktiviert. Vielleicht hilft das vorab schon mal weiter...

Das ist interessant. Wir gehen dem gleich mal nach. Nicht das wir im Zuge des Umbaus da einen Bug eingefangen haben.

[poohnet]

Hallo zusammen,

ich habe mir jetzt mal die "warp4mb"-Version gebaut und manuell via esptool.py auf meinen ESP32 (DevKit V4) geflashed (dann muss ich den WARP-Charger nicht schon wieder auseinanderbauen 🙃).

Der Crash lässt sich auch hier reproduzieren, sobald man MQTT aktiviert.

ets Jun  8 2016 00:22:57

rst:0xc (SW_CPU_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:2
load:0x3fff0018,len:4
load:0x3fff001c,len:976
ho 0 tail 12 room 4
load:0x40078000,len:10124
load:0x40080400,len:5828
entry 0x400806a8
30              **** TINKERFORGE WARP CHARGER V1.3.0-61a4f380 ****
31                   278K RAM SYSTEM   232796 HEAP BYTES FREE
32          READY.
Checking if spiffs is mountable as SPIFFS. Please ignore following SPIFFS errors
E (43) SPIFFS: mount failed, -10025
Checking if coredump is mountable as LittleFS. Please ignore following LittleFS errors
../components/esp_littlefs/src/littlefs/lfs.c:1071:error: Corrupted dir pair at {0x0, 0x1}
E (58) esp_littlefs: mount failed,  (-84)
E (61) esp_littlefs: Failed to initialize LittleFS
E (66) esp_littlefs: Partition was never registered.
Checking if spiffs is mountable as LittleFS. Please ignore following LittleFS errors
115         Mounted configuration partition. 8192 of 262144 bytes (3.1 %) used
195         WARP Charger SPIFFS version 1.3.0-61a29020
498         efuse error: malformed passphrase!
498         efuse error: malformed passphrase!
499         efuse error: malformed passphrase!
509         efuse error: malformed passphrase!
[   587][E][vfs_api.cpp:102] open(): /spiffs/wifi_ap_config does not exist, no permits for creation
[   593][E][vfs_api.cpp:102] open(): /spiffs/wifi_ap_config.json.tmp does not exist, no permits for creation
[   600][E][vfs_api.cpp:102] open(): /spiffs/wifi_ap_config.json does not exist, no permits for creation
725         Had to configure softAP IP address 1 times.
2726        Soft AP started.
2726            SSID: warp-1
2727            hostname: warp-1
2730            IP: 10.0.0.1
2736        mDNS responder started
Guru Meditation Error: Core  1 panic'ed (LoadProhibited). Exception was unhandled.

Core  1 register dump:
PC      : 0x4008a8e4  PS      : 0x00060830  A0      : 0x80089c1d  A1      : 0x3ffb1f90  
A2      : 0x00006465  A3      : 0x00006461  A4      : 0x000000ff  A5      : 0x0000ff00
A6      : 0x00ff0000  A7      : 0xff000000  A8      : 0x8008f20c  A9      : 0x3ffb1f70  
A10     : 0x00000003  A11     : 0x00060823  A12     : 0x00060820  A13     : 0x00000007
A14     : 0x00000005  A15     : 0x00000001  SAR     : 0x00000008  EXCCAUSE: 0x0000001c  
EXCVADDR: 0x00006465  LBEG    : 0x400894b9  LEND    : 0x400894db  LCOUNT  : 0xffffffff


Backtrace:0x4008a8e1:0x3ffb1f900x40089c1a:0x3ffb1fa0 0x40089c09:0x3ffb1fc0 0x40138dc5:0x3ffb1fe0 0x40139e88:0x3ffb2000 0x4013a67f:0x3ffb2040 0x400f3958:0x3ffb2090 0x400e18bd:0x3ffb21e0 0x40107dee:0x3ffb2820 

 

Und hier jetzt der dekodierte Backtrace:

0x4008a8e1: strlen at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/machine/xtensa/strlen.S:43
0x40089c09: strdup at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/string/strdup.c:10
0x40138dc5: set_if_config at /esp32-arduino-lib-builder/build/../esp-idf/components/mqtt/esp-mqtt/mqtt_client.c:348
 (inlined by) set_if_config at /esp32-arduino-lib-builder/build/../esp-idf/components/mqtt/esp-mqtt/mqtt_client.c:344
0x40139e88: esp_mqtt_set_config at /esp32-arduino-lib-builder/build/../esp-idf/components/mqtt/esp-mqtt/mqtt_client.c:407 (discriminator 2)
0x4013a67f: esp_mqtt_client_init at /esp32-arduino-lib-builder/build/../esp-idf/components/mqtt/esp-mqtt/mqtt_client.c:765
0x400f3958: Mqtt::setup() at /home/pooh/esp32-firmware/software/src/modules/mqtt/mqtt.cpp:278
0x400e18bd: setup() at /home/pooh/esp32-firmware/software/src/main.cpp:148
0x40107dee: loopTask(void*) at /home/pooh/.platformio/packages/framework-arduinoespressif32/cores/esp32/main.cpp:38

Im MQTT-Modul wurde ja tatsächlich etwas geändert.

Gruß Thomas

 

P. S. Für weitere Tests habe ich mir jetzt mal den neuen ESP32 Ethernet Brick bestellt...

[photron]

1 hour ago, poohnet said:

Der Crash lässt sich auch hier reproduzieren, sobald man MQTT aktiviert.

Ich kann das hier auch nachstellen. Da haben wir einen Bug eingebaut. Sorry! Wir gehen dem nach. Danke fürs melden.

[poohnet]

Moin,

vielen Dank für‘s Nachstellen. Letztendlich ist so ein Bug zwar ärgerlich, da man den WARP-Charger auseinandernehmen und den ESP32-Brick ausbauen muss, aber mit so etwas muss man ja immer rechnen, wenn man auf einer Entwicklungsversion unterwegs ist.

Die Vorteile eines offenen Systems machen solche „Wehwehchen“ m. E. aber mehr als wett! 👍 

Gruß Thomas

[rtrbt]

https://github.com/Tinkerforge/esp32-firmware/commit/f25ea41db9f65459cf4a27c9d17cd6c212a24954

sollte das Problem gelöst haben. Ich hatte in

https://github.com/Tinkerforge/esp32-firmware/commit/3a77faec23b6557dbb4c91a1c0fc062b0f1390b2

alle Designated Initializers aus dem Code geworfen, weil das eher C-Stil ist und die C++-Compiler sich (berechtigterweise) darüber beschweren. Bei der Initialisierung der MQTT-Config fehlten aber die geschweiften Klammern, damit erstmal alles auf 0 (technisch gesehen: auf die jeweiligen defaults) initialisiert wird. Das führte dann dazu, dass esp-mqtt versucht hat die Länge des nicht initialisierten Last-Will-Topics zu bestimmen:

https://github.com/espressif/esp-mqtt/blob/89894bd0c611b1392967fe90bb49682eba858383/mqtt_client.c#L407

(einem Wert den wir nicht schreiben, das kommt eventuell noch, siehe https://github.com/Tinkerforge/esp32-firmware/issues/34). Daher dann der Crash.

Nochmal danke fürs melden!

[poohnet]

7 hours ago, rtrbt said:

Nochmal danke fürs melden!

Gerne, ich bin immer froh, wenn ich helfen kann 🙂

[poohnet]

Ich kann übrigens bestätigen, dass das Problem nun behoben ist:

ets Jun  8 2016 00:22:57

rst:0xc (SW_CPU_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:2
load:0x3fff0018,len:4
load:0x3fff001c,len:976
ho 0 tail 12 room 4
load:0x40078000,len:10124
load:0x40080400,len:5828
entry 0x400806a8
34              **** TINKERFORGE WARP CHARGER V1.3.0-61a63cc5 ****
35                   308K RAM SYSTEM   231439 HEAP BYTES FREE
35          READY.
97          Mounted configuration partition. 8192 of 262144 bytes (3.1 %) used
184         WARP Charger SPIFFS version 1.3.0-61a29020
487         efuse error: malformed passphrase!
487         efuse error: malformed passphrase!
488         efuse error: malformed passphrase!
498         efuse error: malformed passphrase!
729         mDNS responder started
788         No EVSE Bricklet found. Disabling EVSE support.
789         No RS485 Bricklet found. Disabling energy meter support.
835         No NFC Bricklet found. Disabling NFC support.
873         Had to configure softAP IP address 1 times.
2874        Soft AP started.
2874            SSID: warp-1
2874            hostname: warp-1
3352            IP: 10.0.0.1
3367        Connecting to HMW-IoT
6387        Connected to HMW-IoT
6442        Got IP address: ... Connected to BSSID ...
6447        Network connected. Stopping soft AP
6487        MQTT: Connected to broker.

 

bearbeitet November 30, 2021 at 15:29 von poohnet

[poohnet]

Hallo zusammen,

ich muss das Topic für die aktuelle Beta-Software leider nochmal aufmachen.

Wenn man diese auf einen ESP32-(Ethernet)-Brick flashed, ohne dass das EVSE-Modul angeschlossen ist, dann wird zunächst zwar korrekt "No EVSE Bricklet found. Disabling EVSE support." protokolliert, in der Methode "DeviceName::updateDisplayType()" wird anschließend aber trotzdem ungeprüft per "api.getState()" auf "evse/hardware_configuration" zugegriffen, was in der Folge dann wieder zu einem Crash führt. 🔥

Kurz zuvor wird noch die folgende Fehlermeldung protokolliert:

5,200  Key evse/hardware_configuration not found. Contents are:
5,200  info/version,
5,200  info/modules,
5,211  info/features,
5,211  network/config,
...

Klar, das Szenario betrifft jetzt vielleicht nicht soooo viele User, da das EVSE-Bricklet im WARP-Charger ja eigentlich immer vorhanden sein sollte. Wenn man aber (so wie ich) einen separaten ESP32-(Ethernet)-Brick für Entwicklung und Tests verwendet, dann ist das etwas "unschön"...

Besten Dank & Gruß Thomas

 

EDIT: Idee für Codeanpassung:

void DeviceName::updateDisplayType() {
#if defined BUILD_NAME_WARP || defined BUILD_NAME_WARP2
    String display_type = "WARP";

    if (api.hasFeature("evse")) {
        if (api.getState("evse/hardware_configuration")->get("evse_version")->asUint() >= 20) {
            display_type += "2";
        }

        display_type += " Charger ";

        display_type += api.hasFeature("meter") ? "Pro " : "Smart ";

        display_type += api.getState("evse/slots")->get(1)->get("max_current")->asUint() <= 20000 ? "11" : "22";
        display_type += "kW";
    }
    else {
        display_type += " Charger w/o EVSE Module";
    }

    if (api.hasFeature("nfc")) {
        display_type += " +NFC";
    }

    if (api.hasFeature("rtc")) {
        display_type += " +RTC";
    }
#elif defined BUILD_NAME_ESP32
    String display_type = "ESP32 Brick";
#elif defined BUILD_NAME_ESP32_ETHERNET
    String display_type = "ESP32 Ethernet Brick";
#endif

    if (name.get("display_type")->updateString(display_type)) {
        logger.printfln("This is %s (%s), a %s", display_name.get("display_name")->asCStr(), name.get("name")->asCStr(), name.get("display_type")->asCStr());
    }
}

 

bearbeitet March 19, 2022 at 16:50 von poohnet

[rtrbt]

Ah, das ist kaputt. Danke für den Hinweis. Habe es hier gefixt: https://github.com/Tinkerforge/esp32-firmware/commit/b949541eb5af705563bca5abef5657e49dda550e