ESP RGBWW Controller - Firmware v5

[pjakobs]

so, der neueste Build schickt Diagnosedaten über mqtt an lightinator.de und ich kann mir dann hier auf einem Dashboard anschauen, was passiert.
Auf mqtt sieht das so aus:
Du darfst diesen Dateianhang nicht ansehen.

ich bekomme daraus folgende Informationen:

Code Auswählen Erweitern

{
  "time":3243673,
  "uptime":1860,
  "freeHeap":26704,
  "firmware":
  "V5.0-474-develop",
  "soc":
  "esp8266",
  "mDNS":
  {
    "received":27281,
    "replies":17554
  }
}

Wenn das System neu gestartet wurde und der reboot code != 0 ist, dann bekomme ich zudem die reset daten:

Code Auswählen Erweitern

struct rst_info{
    uint32 reason;
    uint32 exccause;
    uint32 epc1;
    uint32 epc2;
    uint32 epc3;
    uint32 excvaddr;
    uint32 depc;
};

Im Moment gibt es kein UI für die Funktion, die wird nachgeliefert. Ich bitte Euch hier um Euer Vertrauen, dass ich keine in irgendeiner Weise persönlichen Daten übertragen werde.

Hoffentlich können wir damit den seltsamen Restarts auf die Schliche kommen

[weini]

Habe die 476 als Debug-Build installiert. Das Update lief diesmal erfreulicherweise auf Anhieb sauber durch.
Brauchst du meine Device-ID? Die ist ja nicht vertraulich, die könnte ich hier posten, oder?

[pjakobs]

ich sehe jetzt 28 Controller live, nur 11 davon sind meine.
im Moment kämpfe ich noch damit, das Dashboard auf die neue Datenquelle umzustellen (bei meinen eigenen Controllern habe ich nur den /info api Endpoint gescraped)
Ich hoffe auch, dass ich heute auch noch eine Firmware bauen kann, wo Ihr das MQTT reporting abschalten könnt.

pj

[rippi46]

Hallo,

16 könnten von mir sein!

Gruß rippi

[pjakobs]

immerhin ein bisschen Daten:

Code Auswählen Erweitern

mqtt_flattened_output/228427.jsonl:{"id": 228427, "time": 202595, "uptime": 0, "freeHeap": 24552, "firmware": "V5.0-476-develop", "soc": "esp8266", "reboot_reason": 4, "reboot_exccause": 0, "reboot_epc1": 0, "reboot_epc2": 0, "reboot_epc3": 0, "reboot_excvaddr": 0, "reboot_depc": 0, "mDNS_received": 713}
mqtt_flattened_output/228427.jsonl:{"id": 228427, "time": 202809, "uptime": 0, "freeHeap": 24960, "firmware": "V5.0-476-develop", "soc": "esp8266", "reboot_reason": 4, "reboot_exccause": 0, "reboot_epc1": 0, "reboot_epc2": 0, "reboot_epc3": 0, "reboot_excvaddr": 0, "reboot_depc": 0, "mDNS_received": 932}
(das ist der gleiche Controller 2x, für den gleichen Reset, ich dachte, ich hätte das unterbunden)

reboot_reason 4 ist, wenn ich das nicht falsch gesehen habe ein software reset.
Ich könnte ja einen hardware oder software watchdog reset verstehen, aber software reset wäre
etwas, was as Programm von sich aus tun würde.

Tatsächlich gibt es ein paar Bedingungen, unter denen die Firmware den Controller neu startet:
- während des OTA, wenn das neue ROM image erfolgreich geflasht worden ist
- nach einem OTA wenn der Controller im temporary boot mode gestartet ist
- wenn Ihr die boot Partition wechselt
- wenn das Frontend eine Veränderung vornimmt, die einen Restart erfordert (geändertes Color Model, geänderter Hostname, geänderte Pins etc) oder, wenn Ihr den Reboot Knopf gedrückt habt

Code Auswählen Erweitern

0 Power reboot
1 Hardware WDT reset
2 Fatal exception
3 Software watchdog reset
4 Software reset
5 Deep-sleep
6 Hardware reset
Was es jetzt war geben die Daten, die ich hier einsammle gerade nicht her.

[weini]

Die "id" ist vermutlich die Device-ID, oder? Dann ist das nicht meiner - kann ich leider nichts dazu sagen.

[rippi46]

Hallo,

der 228427 ist von mir.

Mit dem habe ich ständig Probleme.
Keine Ahnung was der hat. Verändert ab und zu die Helligkeit oder ist nicht mehr erreichbar.
Vielleicht ist ja der Chip hinüber.

Gruß rippi

[pjakobs]

es zeichnet sich langsam ein Bild ab, aber ich weiß nicht, was es bedeutet:
Seit gestern haben wir unter den 29 Controllern die sich melden fünf reboots und alle haben "reboot_reason: 4" (10981722, 10982642, 10982926, 228427, 5952201) - in einem Fall waren nur noch 14kB Heap frei - das ist aber eigentlich kein Problem. (gut, die Auflösung ist 30s, da kann viel passieren, aber noch öfter würde das Reporting selbst zur Belastung machen)
Zudem sollte, wenn die Controller crashen, weil der Speicher ausgeht die reboot reason eher 2 (Fatal exception) sein, und es gäbe einen "reboot_epc1" - die Code Adresse, an der der Fehler aufgetreten ist.

Das sieht alles so aus, als würde der Controller aus der Firmware heraus gesteuert neu starten, aber dafür sehe ich keinen Grund.

[pjakobs]

in den letzten zwei Stunden sind 10 von 26 Controllern neu gestartet - allerdings ist die Zahl der Controller auch ziemlich plötzlich um fünf gestiegen! Da hat doch jemand das Licht eingeschaltet!

Wobei ich dann als Reboot Reason 0 erwarten würde.
Du darfst diesen Dateianhang nicht ansehen.

[pjakobs]

das ist schon wirklich seltsam.
Mir war nicht bewusst, wie weit der Speicherbedarf der Controller spreizt - sicher, das hängt davon ab, wieviel im jeweiligen Netz "los" ist und sicher auch davon, wie sie genutzt werden, aber ich sehe in den Daten, dass ein Controller (13872384) unter 16kB frei hat und das schon seit geraumer Zeit, Trend abnehmend. Andere (10964518) haben über 27kB frei - und trotzdem laufen beide seit mehr als 24h stabil (ich weiß, das Ziel sollten 100e Tage sein, nicht ein paar 10 Stunden)
Meine Controller seen ziemlich viel mDNS Traffic - 6668181 etwa fast 2.5 Millionen Pakete in knapp zwei Tagen - was aber scheinbar kein Problem ist.
Es gibt auch keinen sichtbaren Zusammenhang zwischen der ID und dem Fehlerverhalten - manche (vermeintlich ältere) Chips mit sechsstelliger ID laufen relativ stabil, andere mit siebenstelliger (vermeintlich neuer) haben in den letzten zwei Stunden Reboots hingelegt. Einer meiner Gedanken war ja, dass vielleicht die sehr alten Controller, die ursprünglich noch ohne Partitionen ausgeliefert wurden möglicherweise ein Problem hätten, aber - das spricht nicht dafür.

[pjakobs]

auch interessant: 18372384, 7918126, 228427 und andere haben eindeutig abnehmenden freien RAM in der Größenordnung von 2kB in sechs Stunden
Du darfst diesen Dateianhang nicht ansehen.

6737456, 6668181, 5952201, 5951704, und andere hingegen bleiben völlig stabil
Du darfst diesen Dateianhang nicht ansehen.

Und das korreliert negativ (!) mit dem mDNS Traffic im Netz. Das verstehe wer will.

[weini]

Nettes Detektivspiel 

Meiner (ID 13872384) ist jetzt auf 11,5k Free Heap runter.
Ich würde den nächsten Reboot abwarten, damit wir sehen, ober er auch mit Code 4 durchstartet.

Danach könnte ich ihn mal in mein Guest WiFi hängen. Da ist nichts los. Es sollte kein mDNS Traffic auftreten und es kann auch zu keinem Roaming kommen, weil mein Guest WiFi nur auf dem Haupt-Router läuft. Würde dir das helfen?

Ich bin mir immer noch recht sicher, dass ich mit der 424 noch deutlich längere Laufzeiten hatte. Mit der 429 hatte ich auch die Reboots innerhalb von 1-3 Tagen. Hast du zwischen den beiden Versionen vielleicht irgendwelche Bibliotheken in einer neuern Version eingebunden?

[pjakobs]

noch hält er durch  Aber es ist wirklich erstaunlich, es setzt sich gerade eine Gruppe Controller ab - nach unten.
Das ist mir völlig schleierhaft, denn ich finde keine Korrelation zu anderen Parametern, die vom Umfeld auf die Controller einwirken (deshalb hab ich die mDNS pakete gezählt, da kommen ein paar 10 pro Sekunde (bei mir) die natürlich alle irgendwie Speicher belegen - auch wenn sie gleich verworfen werden.
Ich bin sehr gespannt, was das ist.
Du darfst diesen Dateianhang nicht ansehen.

[pjakobs]

so, leider hat's irgendwann heute Nacht lightinator.de zerlegt, der Server, auf dem der MQTT Server läuft mit dem die Controller sprechen - und scheinbar ist der Code, mit dem die Controller sich wieder verbinden sollen noch nicht robust genug uns sie tun genau das nicht.
Die Daten von gestern sind aber immerhin schonmal recht interessant.
- es gibt Controller die zeigen deutlich Anzeichen eines Memory Leaks
- es gibt andere, die scheinen, wie man es eigentlich erwartet, etwa konstanten Speicherverbrauch zu haben.
Das sagt mir: es gibt ein Memory Leak in einem Codepfad, den nicht alle gleich häufig durchlaufen, mein erster Verdacht war der mDNS Pfad, aber ich habe nicht wirklich eine Korrelation von mDNS Traffic und Speicherverbrauch gesehen.
Ich werde im Laufe des Tages noch ein bisschen mehr Messpunkte einbauen und eine neue Version pushen.

Einen Reboot habe ich gestern noch gesehen, der mit reboot_reason 1 daher kam, das war eher das, was ich so erwartet hätte, das ist HARDWARE_WDT_RESET also der Hardware Watchdog Timer. Da hing irgendein Task und der Controller hat gezielt neu gestartet (die Philosophie hinter solcher Firmware ist: lieber neu starten als einen hängenden Controller).
In dem Fall habe ich eine Adresse und kann mir ansehen, was da passiert ist.

Ich will für die nächste Version auch etwas einbauen, das es mir (und Euch) leichter macht, zu identifizieren, *wessen* Controller das sind, um ggf. nachfragen zu können, was da im Netz passiert.
Allerdings will ich das auch machen, ohne, dass ich zu viel identifizierbare Daten sammle. Ich könnte
- den WiFi Namen
- den Controller Namen
- die IP Adresse
einsammeln - alle haben so ihre Probleme - der WiFi Name kann manchmal generisch sein (gerne bei FritzBoxen, wo der original Name nicht geändert wurde), der Controller Name sagt oft was über Euch aus (etwa in welchem Raum er ist etc) und die IP Adresse ist wieder nicht immer eindeutig, gerade, wenn Ihr einfach 192.168.1.0/24 nutzt.
Ich glaube aber, die IP Adresse ist das am einfachsten zu identifizierende Merkmal, zur Not guckt Ihr einfach drauf und vergleicht die id.
Ist das für Euch okay, wenn ich zusätzlich die IP Adresse übertrage?
(btw, das ganze läuft in eine InfluxDB und die ist so konfiguriert, dass Daten nach 30 Tagen automatisch gelöscht werden)

Ich guck nachher mal durch und schau, welche Controller zu der Gruppe gehören, die offenbar Speicher "verbrauchen" und poste die vollständige Liste, vielleicht könnt Ihr mir da dann schon was erzählen, aber wir wissen ja schon, dass 13872384 @weini gehört und der gehört zu der Gruppe mit vergleichsweise vielen mDNS Paketen aber der lief, trotz extrem wenig freiem RAM zwei Tage durch - 10982642 und und 10981722 hingegen hatten noch genug freien RAM, sind aber neu gestartet.
Einschränkung dabei: ich sehe den Speicher nur alle 30s, in 30s kann viel passieren. Ich überlege auch, ob ich die zeitliche Auflösung verbessere ohne, dass ich mehr Traffic erzeuge (etwa jede Sekunde die Daten abfragen, und in einem Array verschicken)
Das Problem ist dabei natürlcih immer: ich will nicht durch das Daten Sammeln selbst mehr Druck auf das System ausüben.
Spannendes Spiel.

Eigentlich müsste ich Dir ein Bug Bounty geben, Weini

pj

PS: funfact am Rande: der Server blieb wegen eines Memory Leaks hängen. Toll, oder?

[weini]

Habe um 18:15 nochmal das Web-UI aufgerufen, das hat ihn dann gekillt 
Free Heap war runter bis auf 8,4k.

Jetzt habe ich dem Controller ein eigenes WLAN spendiert und dafür das Roaming deaktiviert. Wir werden sehen, ob das was ändert.
Durch den Reboot sollte er auch wieder mit dem MQTT Server verbunden sein. Der mDNS Traffic sollte sich nicht ändern, weil das WLAN in meinem Hauptnetz hängt.

Alternativ kann ich ihn auch in mein Guest-Wifi hängen, da sollte kein mDNS auftreten.

Ich fand übrigens die Identifikation über die Controller ID völlig ausreichend. Die kann man doch im WebUI nachlesen. Aber mit der IP habe ich jetzt auch kein Problem.