[node-blue] Fehler im Nightly 20191220 / erledigt

[job]

Das aktuelle nightly hat einen Fehler in Node-Blue. Dieser Fehler verursacht hohe Rechenlast, ein dauernde Verbindungsverluste der Weboberfläche.

Folgende Fehlermeldung tritt dauernd auf:

12/18/19 00:34:36.236 Node-BLUE (21279): Node 29fbd588.18664a:e1cbd6c1.853558: Unknown error in file MyNode.cpp line 199 in function virtual void MyNode::Template::input(Flows::PNodeInfo, uint32_t, Flows::PVariable).

Es sind Template-Nodes. Das payload ist als mustache-Template deklariert, drin steht aber nur ein RGB-Farbcode z.B. #FF0000. Die Ausgabe ist plain text.

Mit der Version vom 30.11.2019 ist das Problem wieder weg.

[sathya]

Hallo @job,

vielen Dank, das schaue ich mir gleich an.

Viele Grüße

Sathya

[job]

Perfekt. Ist auch wichtig, dadurch ist die aktuelle Version bzgl. Node blue unbrauchbar.

Vielleicht geht es schnell, und du kannst noch einen blick auf das Gateway-Problem werfen.

[sathya]

Könntest du einmal testen, ob es funktioniert, wenn du statt “Parsed JSON”, “Plain text” auswählst? Ich weiß, dafür musst du wieder aktualisieren… Aber das wäre das einzige, was ich gerade als Fehler sehe…

[job]

Du meinst statt “plain text” “parsed json” einstellen, oder?

[sathya]

Nee, “Plain text” auswählen. Bei dir ist bereits “Plain text” ausgewählt?

[job]

Ja. Genau.

Ich schau mal nach, ob vielkeicht eine Template node falsch steht. Sind ja ein paar.

[job]

Mist. Eine stand auf “parsed Json” als Ausgabe…

Aber warum zieht das das System so immens runter? Das ist das größere Problem. Last ist auf allen 4 Kernen (pi3b+) von ca. 10% auf ca. 50% gestiegen und die Node-Blue Oberfläche war unbedienbar.

Soll ich nochmal das Upgrade probieren?

[sathya]

Aber warum zieht das das System so immens runter? Das ist das größere Problem. Last ist auf allen 4 Kernen (pi3b+) von ca. 10% auf ca. 50% gestiegen und die Node-Blue Oberfläche war unbedienbar.

Das liegt daran, dass im JSON-Decoder eine Endlosschleife ausgelöst wurde. Der Fehler ist jetzt gefixt.

Soll ich nochmal das Upgrade probieren?

Gerne. Das würde mir sehr helfen, um zu verifizieren, ob das tatsächlich das Problem war.

[job]

Upgrade fertig. Sieht nicht gut aus. Prozessorlast immens gestiegen, obwohl nichts anderes mehr drauf läuft als Homegear.

[sathya]

Hmm, und kein Template mit nur einem String verwendet mehr “Parsed JSON”?

[job]

nur einem String verwendet mehr “Parsed JSO

Naja, das kann ich nicht sagen, es gibt allerdings die Fehlermeldung nicht mehr.
Dafür das:

12/18/19 19:38:59.858 Node-BLUE (25167): Warning: Node output queue has 2354 entries.
12/18/19 19:39:00.262 Node-BLUE (25229): Warning: Node output queue has 1816 entries.
12/18/19 19:39:00.859 Node-BLUE (25167): Warning: Node output queue has 2383 entries.
12/18/19 19:39:01.354 Node-BLUE (25229): Warning: Node output queue has 1831 entries.
12/18/19 19:39:01.861 Node-BLUE (25167): Warning: Node output queue has 2404 entries.
12/18/19 19:39:02.355 Node-BLUE (25229): Warning: Node output queue has 1844 entries.
12/18/19 19:39:02.863 Node-BLUE (25167): Warning: Node output queue has 2434 entries.
12/18/19 19:39:03.360 Node-BLUE (25229): Warning: Node output queue has 1859 entries.
12/18/19 19:39:03.864 Node-BLUE (25167): Warning: Node output queue has 2468 entries.
12/18/19 19:39:04.368 Node-BLUE (25229): Warning: Node output queue has 1873 entries.
12/18/19 19:39:04.866 Node-BLUE (25167): Warning: Node output queue has 2494 entries.
12/18/19 19:39:05.441 Node-BLUE (25229): Warning: Node output queue has 1888 entries.
12/18/19 19:39:05.867 Node-BLUE (25167): Warning: Node output queue has 2523 entries.
12/18/19 19:39:06.444 Node-BLUE (25229): Warning: Node output queue has 1902 entries.

Noch etwas festgestellt, der Verbindungsverlust ist anscheinend dadurch begründet, das Homegear neu startet. Ich suche mal die Stelle im Log.

Da läuft anscheinend irgendwas voll, was mit der Fehlermeldung viel schneller passiert ist. Da hatte ich nicht mal Zeit ein paar Nodes anzuschauen.

So, das ist jetzt ein Log des Problems. Anscheinend werden die node output queues nicht mehr vollständig abgearbeitet, wodurch nach gewisser Zeit ein Watchdog den Prozess abschiesst.

==> /var/log/homegear/homegear-flows.log <==
12/18/19 19:55:04.884 Node-BLUE (10215): Warning: Node output queue has 2731 entries.
12/18/19 19:55:05.354 Node-BLUE (10276): Warning: Node output queue has 1780 entries.
12/18/19 19:55:05.959 Node-BLUE (10215): Warning: Node output queue has 2698 entries.
12/18/19 19:55:06.207 Node-BLUE (10215): Error in lifetick: More than 1000 items are queued in queue number 2
==> /var/log/homegear/homegear.log <==
12/18/19 19:55:06.213 Critical: Node-BLUE server lifetick failed.
==> /var/log/homegear/homegear-flows.log <==
12/18/19 19:55:06.248 Node-BLUE (10276): Connection to flows server closed (2). Exiting.
12/18/19 19:55:06.248 Node-BLUE (10276): Error: Shutdown is not complete. Killing process...
12/18/19 19:55:06.252 Node-BLUE (10215): Connection to flows server closed (2). Exiting.
12/18/19 19:55:06.252 Node-BLUE (10215): Error: Shutdown is not complete. Killing process...
==> /var/log/homegear/homegear.log <==
12/18/19 19:55:06.972 Starting Homegear...
12/18/19 19:55:06.972 Homegear version 0.8.0-2835
12/18/19 19:55:06.972 Git commit SHA of libhomegear-base: -

@sathya, Gibt dir das Anhaltspunkte?

[job]

Nur zur Info, das ist die Last nach Rückkehr auf 20191130:

[sathya]

Hallo @job,

letztlich waren es sogar zwei Fehler. Einer beim JSON parsen und einer, welcher die falsche Anzeige von Fehlermeldungen bewirkt hat. Beide sind jetzt behoben. Ich würde vorschlagen, wir probieren es noch einmal mit dem nächsten Nightly. Bei mir funktioniert nach den Anpassungen die Template-Node jetzt jedenfalls wie erwartet. Ich hoffe, bei dir auch. Falls nicht, muss ich noch einmal tiefer schauen.

Viele Grüße

Sathya

[job]

Hi @sathya,

leider hilft das neue nightly nicht. Es gibt zwar keine Fehlermeldung, aber homegear/node-blue startet sich nach ein paar Minuten neu.

12/21/19 03:52:20.751 Node-BLUE (30871): Warning: Node output queue has 1113 entries.
12/21/19 03:52:21.105 Node-BLUE (30871): Error in lifetick: More than 1000 items are queued in queue number 2
12/21/19 03:52:21.106 Critical: Node-BLUE server lifetick failed.
12/21/19 03:52:21.752 Node-BLUE (30871): Warning: Node output queue has 1143 entries.

Bin wieder zurück auf nightly vom 30.11.

Viele Grüße

Joachim

[sathya]

Hallo @job,

da scheint irgend ein Knoteneingang zu hängen. Ich habe leider nicht geschaft zu identifizieren, welcher. Du würdest mir einen riesen Gefallen tun, wenn du bei dir durch Deaktivieren von Flows und Knoten (geht in aktuellen Versionen auf der “Knoten bearbeiten”-Seite identifizieren könntest, an welchem Knoten es liegt…

Viele Grüße

Sathya

[job]

Hi @sathya,

Ich glaube ich habe es isoliert: es war vermutlich die Round-Robin-Node. Du hast den Rückwärts-Eingang hinzugefügt, dadurch wurde der Trigger, der eigentlich auf Reset ging, auf den Rückwärtsschritt umgestellt. Mit einem etwas unglücklichen Eingang wurden dadurch dann zig Messages generiert.

Ich beobachte mal weiter.

Viele Grüße

Joachim

[sathya]

Hallo @job,

puh, da bin ich erleichtert, dass das Problem gefunden ist. Ja ja, “breaking changes”…

Viele Grüße

Sathya