ESP RGBWW Controller - Firmware v5

[pjakobs]

@mafi - wenn Du die Zeit hast, mach doch bitte mal ein Update auf die pj-1-632-gc15f (jetzt im OTA Stream) und schau, ob Du den gleichen Fehler bekommst, wenn ja, dann kann ich den stack dump besser troubleshooten.

[Mafi]

Update hat geklappt. Der Fehler ist jetzt nach 6 Minuten noch nicht wieder aufgetreten. War ja vorher alle 60s.
Ich beobachte das mal weiter, aber auf jeden Fall hat sich was verbessert. Ich denke morgen kann ich mehr sagen. Aber sieht vielversprechend aus! Danke!

[pjakobs]

Update hat geklappt. Der Fehler ist jetzt nach 6 Minuten noch nicht wieder aufgetreten. War ja vorher alle 60s.
Ich beobachte das mal weiter, aber auf jeden Fall hat sich was verbessert. Ich denke morgen kann ich mehr sagen. Aber sieht vielversprechend aus! Danke!

das wäre natürlich spitze!

Ich habe ein bisschen den Verdacht, dass es mit dem genutzten FLASH Block zu tun haben könnte, es gibt zwei, die für die Firmware genutzt werden: rom0 und rom1.
Nach einem OTA bist Du jeweils im anderen Block (rom0->rom1 bzw rom1->rom0). Nur das Flash File System ist immer gleich.

Bin gespannt, wie es sich entwickelt.

[Mafi]

Am genutzten Flashblock wird es nicht gelegen haben, denn ich hatte ja nach dem ersten seriellen Mitschnitt nochmal ein Update auf die Debugversion gemacht. Dabei wurde dann ja auf den anderen Bereich gewechselt. Der Fehler trat aber genauso weiter auf.
Heute Morgen funktionierte jedenfalls immer noch alles. Was immer es war, es scheint mit der neuen Version gelöst zu sein. Ich werde diesen Controller weiter aktuell halten wenn es neue Versionen gibt und berichten, falls irgend etwas auffällt.

Wenn ich einen Wunsch äußern dürfte: Ich fände es gut, wenn der Wert Config-Color-Startup_Color auch im Webinterface gesetzt werden könnte. Ich habe die Controller immer auf einen festen Wert eingestellt, damit das Flash geschont wurde. Über das Reading in FHEM war das immer recht umständlich zu machen, zumal laut Doku bei Angabe eines falsch formatierten Werts auch der Controller crashen konnte.

[Mafi]

Tja, leider zu früh gefreut. Der Fehler ist wieder da! Mitschnitt im Anhang.
Keine Ahnung, was jetzt anders sein soll als heute morgen.

[pjakobs]

okay, das ist interessant und das hab ich noch nicht gesehen.

Der Fehler passiert im IGMP Modul (Internet Group Management Protocol) - das gehört zum Multicast Protokoll. Die Controller beherrschen aber kein Multicast bzw nutzen das nicht.
Hast Du Multicast Geräte laufen? Also etwa Multi-Room WiFi Musiksysteme oder sowas?

Ich könnte mir gut vorstellen, dass dieser Code innerhalb des ip Stacks sehr alt und ggf. buggy ist (ich hab schon zwei Bugs in LwIP gefunden), allerdings habe ich leider wenig Möglichkeit, das zu debuggen.

Ich will mal sehen, ob ich Dir einen Build mit LWIP debug enabled bauen kann. Du kannst zur not auch seriell flashen, oder?

Code Auswählen Erweitern

0x402201ea: igmp_input at /opt/Sming/Sming/Arch/Esp8266/Components/esp-open-lwip/esp-open-lwip/lwip/core/ipv4/igmp.c:458
0x40223021: pbuf_alloc at /opt/Sming/Sming/Arch/Esp8266/Components/esp-open-lwip/esp-open-lwip/lwip/core/pbuf.c:389
0x4021f7d8: ip_input at /opt/Sming/Sming/Arch/Esp8266/Components/esp-open-lwip/esp-open-lwip/lwip/core/ipv4/ip.c:569
0x4021f32c: ethernet_input at /opt/Sming/Sming/Arch/Esp8266/Components/esp-open-lwip/esp-open-lwip/lwip/netif/etharp.c:1372
0x40232083: ppRxPkt at /home/xcg/workspace/debug/esp8266_nonos_sdk_core_20180510/app/pp/pp.c:1121
0x40231ff6: pp_tx_idle_timeout at /home/xcg/workspace/debug/esp8266_nonos_sdk_core_20180510/app/pp/pp.c:992
0x4021e0bb: ets_snprintf at ??:?


[pjakobs]

und wenn ich dann mal drüber nachdenke - mDNS (also das Protokoll mit dem sich die verschiedenen Controller finden) nutzt natürlich auch multicast ip - 224.0.0.251 in meinem Fall.
Das bedeutet, dass dieser Code eben doch genutzt wird. Seltsam.
Ich hab mal eine Version mit aktiviertem lwip debug gebaut, mal sehen, ob wir damit mehr erkennen können.
Ist im OTA stream als "lwip_test" zu haben.
Diese Version generiert so richtig viel output, mal sehen, ob ich es damit einkreisen kann.

pj

[Mafi]

Das ging ja schnell! Wenn ich heute Abend dazu komme, werde ich die Version gleich mal installieren. Bin gespannt, ob der Fehler dann wieder sofort auftritt oder erst nach einem Tag. Merkwürdig ist das ganze ja schon.
Ob in meinem Netz viele Multicast Pakete herumschwirren weiß ich nicht. Ich habe eine ganze Hand voll Echos und Echo Dots, sowie FireTV Sticks und Fernsehen läuft über WaipuTV. Schon möglich, dass da für TV oder Lautsprechergruppen auch Multicasts zum Einsatz kommen.

Flashen per serieller Schnittstelle habe ich ewig nicht mehr gemacht, sollte aber immer noch funktionieren, falls nötig.

[Mafi]

So, da sind wir schon. "Generiert so richtig viel output" trifft es kaum. Es ist gigantisch!
Das letzte, was vor dem Crash kommt, ist eine Anfrage von Adresse 192.168.178.21. Es hilft vielleicht zu wissen, was das ist. Unter der Adresse verbirgt sich ein TP Link TL-WA890EA WLAN Bridge Device, das mein WLAN auf Ethernet übersetzt (also ein WLAN Client ist). Daran hängt zur Zeit aber nur noch eine Energernie Steckdosenleiste. Früher auch Bluray Player, Fernseher und Kabelbox. Da der WA890EA schon öfter durch Ausfall glänzte in den letzten Wochen und dann die besagte Steckdosenleiste nicht mehr für FHEM erreichbar ist, wird er in Kürze in Rente geschickt. Gerade heute habe ich Ersatz für die Steckdosenleiste (immerhin schon 10 Jahre alt) bestellt. In Form von Nous A8T WLAN Steckdosen mit Tasmota. Möglicherweise ist die Ursache des Problems dann beseitigt, wenn der WA890EA weg ist. Obwohl der Lightinator natürlich trotzdem nicht so auf die Nase fallen sollte, wenn ein solches Paket kommt. Die anderen, noch mit der alten Software laufenden Platinen haben interessanterweise auch kein Problem.

Viel Erfolg! Ich kann mein Setup gern noch so belassen, um Bugfixes zu testen-

[pjakobs]

sehr schön, damit kann ich schonmal ein bisschen was anfangen.

ich hab diesen Codeblock im Verdacht:

Code Auswählen Erweitern

       groupref = igmp_group_list;
       while (groupref != NULL) { //pj added explicit NULL check
         /* Do not send messages on the all systems group address! */
         if ((groupref->netif == inp) && (!(ip_addr_cmp(&(groupref->group_address), &allsystems)))) {
           LWIP_DEBUGF(IGMP_DEBUG, ("igmp_input: delaying membership on group %i ",groupref)); //pj added message
           igmp_delaying_member(groupref, igmp->igmp_maxresp);
         }
         groupref = groupref->next;
       }

Der Fehler ist ein uneraubter Speicherzugriff, etwa ein Nullpointer, diese Schleife soll alle gültigen multicast Gruppen durchlaufen, ich will mal sehen, ob da was schief geht.

da ich vermute, dass Du jetzt nicht über das UI flashen kannst, kannst Du (Linux oder WSL oder einen anderen http client vorausgesetzt) folgendes eingeben um vom anderen ROM zu booten :

Code Auswählen Erweitern


curl -X POST http://192.168.178.118/system -H 'Content-Type: application/json' --data '{"cmd":"switch_rom"}'

damit sollte wieder der Code ohne so viel debug output laufen und das UI zugänglich sein, und Du solltest normal den OTA Prozess anstoßen können.

Sollte das nicht funktionieren, kannst Du Dir von http://lightinator.de/download/app-merged.bin das ganze flash image herunterladen und mit

Code Auswählen Erweitern

esptool.py -p <com-port> -b 115200 --chip esp8266 write_flash -z -fs 4MB -ff 40m -fm dio 0x00000 app-merged.bin
flashen.

Es ist möglich, dass der explizite NULL Check das Problem behebt, aber ich gehe davon aus, dass es weiter auftritt, aber ich diesmal sehen kann, welche multicast Gruppen durchlaufen werden.
Entweder damit bestätigt sich diese Stelle als das Problem oder ich muss anderswo suchen.

Mein Eindruck ist, dass, was immer da von dem WA890EA kommt irgendwie einen Bug im lwip code triggert, denn sonstwo hab ich dieses Verhalten noch nicht beobachtet.

Viel Spaß

[Mafi]

Guten Abend!

Hier das neueste Log. Der Fehler tritt weiterhin auf. Man sieht im Mitschnitt, dass auch meine FritzBox (192.168.178.1) IGMP Nachrichten an Adresse 224.0.0.1 sendet. Das führt aber nicht zum Absturz. Nur die Pakete vom WA890EA tun das. Irgend etwas muss an diesen Paketen besonderes sein. Ich habe keine Ahnung vom IGMP Protokoll. Ich sehe nur das bei der FritzBox [igmp_maxresp=100] protokolliert wird, beim WA890 aber [igmp_maxresp=1]. Was immer das bedeutet. Der Fehler tritt vermutlich bei der Verarbeitung des Paketinhalts auf. Der NULL Check scheint leider nicht gewirkt zu haben, da muss es wohl an anderer Stelle krachen.

[pjakobs]

ich glaube, ich hab den Bug gefunden.

Code Auswählen Erweitern

igmp_start_timer(struct igmp_group *group, u8_t max_time)
{
  ip_addr_debug_print(IGMP_DEBUG, &group->group_address);
  LWIP_DEBUGF(IGMP_DEBUG, ("igmp_start_timer for %i",max_time));
  /* ensure the input value is > 0 */
  /* actually, it needs to be > 1 as 1 is subtracted before the modulo */
  if (max_time == 0 ) {
    max_time = 1;
  }
  /* ensure the random value is > 0 */
  group->timer = (LWIP_RAND() % (max_time - 1)) + 1;
}
Dein Router sendet ein igmp paket mit max_time 1, diese Funktion erfordert, dass max_time mindestens 1 ist.
Allerdings wird danach LWIP_RAND() % (max_time - 1) berechnet. %, der Modulo Operator ist der Divisionsrest, also wird hier eine Division durch 1-1 = 0 durchgeführt. Das muss knallen.

Neuer Build ist im OTA Stream und sollte das beheben.

ps: issue gegen Sming: https://github.com/SmingHub/Sming/issues/2936
pj

[Mafi]

Der Fehler tritt leider weiterhin auf.
Ich verstehe auch den Fix nicht recht. Soweit ich den Code verstehe, würde jetzt immer noch durch 0 geteilt, wenn max_time=1. Nur auf das Ergebnis würde dann 1 addiert. Wäre das denn dann korrekt? Es geht ja meinem Verständnis nach darum, eine zufällige Verzögerung mit einem maximalen Wert von max_time zu wählen. Wenn max_time=1 also zwischen 0 und 1. Würde die Formel so nicht zu einem Wert zwischen 1 und 2 führen (die Division durch 0 mal außen vor gelassen)? Aber ich glaube, du hast genau die richtige Stelle gefunden. Im Log sieht man, dass für den Wert 1 der Timer gestartet werden soll und dann knallt es.

[pjakobs]

Der Code hier ist (bis auf meinen Kommentar) der original Code.
Ich hab einen PR gegen Sming, der den Fix backportet, den esp-open-lwip upstream gemacht hat. Ich gehe ziemlich sicher davon aus, dass das das Problem löst.
Ich kann nachher mal eine Version damit bauen.

[pjakobs]

so, ich hab dann nochmal mit dem candidate patch gebaut.

Code Auswählen Erweitern

igmp_start_timer(struct igmp_group *group, u8_t max_time)
{
  group->timer = (u16_t)(max_time > 2 ? (LWIP_RAND() % max_time) : 1);

  if (group->timer == 0) {
    group->timer = 1;
  }
}
Im Grunde macht die Funktion das selbe, aber der div 0 Case kann nicht mehr auftreten, wenn max_time <=2 ist, wird der timer auf 1 gesetzt. Wenn LWIP_RAND()%max_time zufällig 0 sein sollte, wird der timer auf 1 gesetzt.

In Deinem speziellen Fall sollte er also klar definiert 1 sein.

Wie üblich, im OTA Stream.

Warum der vorherige Patch nicht funktioniert hat ist mir nicht ganz klar, da hatte ich eigentlich auch schon auf ">=2" gecheckt. Egal, upstream hat diese Lösung.

Das Problem mit dem IP Stack für den Esp8266 in Sming ist, dass es eine *sehr* alte Version ist (7-9 Jahre). Upstream ist zwischenzeitlich viel gefixt worden, aber im Moment traut sich niemand, das anzupacken, auch weil der 8266 nicht unbedingt eine Zukunftsplattform ist.