IP-Symcon v4.3: Dienst beendet erratisch ohne Hinweis im Log

Guten Abend,

Mein Setup:

[ul]
[li]Raspberry Pi v3
[/li][li]Raspian-Jessie-Lite
[/li][li]IP-Symcon v4.3
[/li][/ul]

Ausgangssituation:
Bin vor ca. etwas mehr als einer Woche auf IP-Symcon v4.3 migriert und danach gleich auf die RasPi umgezogen. Alles sehr einfach und straight forward.

Phänomen:
Vor ein paar Tagen hatte ich beim Zugriff auf das Webfront keine Verbindung. Gleich mal putty hochgefahren und festgestellt, daS kein Symcon Prozess aktiv war. Hab Symcon gleich wieder gestartet und das ganze erstmal ignoriert. Leider war meine Ignoranz nicht mächtig genug… sprich der Spuk geht weiter.

Counter Measures:
Gestern hab ich mich hingesetzt und ein shell-script aus der Taufe gehoben mit dem ich prüfe ob der Symcon Prozess läuft… und falls nicht, sichere ich die hier folgenden log files in einen speziellen Folder den ich dafür anlege:

[ul]
[li]/var/log/syslog
[/li][li]/var/log/messages
[/li][li]/var/log/symcon/logfile
[/li][/ul]
Das script ist auf einer Cron cycle von 2 min.

Status Quo:
Seit gestern hat mein script 2 mal zugeschlagen. Heute um 19:06 und um 20:44. Mit dem script auf Cron hab ich einen maximalen Datenverlust von 2 min… ist aber schon ziemlich nervig… weil das Beenden ohne für mich ersichtlichen Grund sollte so nicht sein.

Meine Bitte an die Experten:
Sagt mir falls ich noch andere Logs oder Informationen einsammeln kann wenn der Symcon Prozess beendet hat. Damit könnte ich Daten liefern die eventuell helfen das Problem einzugrenzen. Und ja, ich hab paresy’s [Debugging für Experten] gelesen… aber ich qualifiziere das einfache Beenden des Symcon Prozess bisher nicht als ‚Absturz‘. Kann natürlich paresy’s Anweisungen folgen falls das helfen sollte.

Grüsse, homa

Wenn der Prozess einfach weg ist, ist die Wahrscheinlichkeit sehr hoch, dass es ein Absturz ist. Es sei denn in den Logfiles steht am Ende eine sauberes „SHUTDOWN“.

Ich würde somit gerne mal den gdb Output sehen - das müsste mehr Informationen bringen. Wie ist deine Auslastung auf dem Pi? Werden ggf. Skripte verworfen? Hängen bei dir Skripte fest? (Expertenansicht -> PHP Informationen)

paresy

ok, der gdb ist gestartet… allerdings deine Anweisung kommt nicht mehr zum Zuge… bei Jessie scheint das nicht aufzutreten.

paresy: Auf dem Raspberry Pi kommen zwei SIGILL Fehler. Diese übergehen wird jeweils mit „c“ und Enter

Jetzt zu Deinen Fragen:

[ul]
[li]Auslastung des Pi: ist ein v3 Pi… einzig mit Symcon beschaeftigt… es laeuft grad der debugger… somit will ich nicht storen, allerdings hab ich mittlerweile 1000 Variablen und etwas ueber 165 Scripte. Ich achte allerdings bei hochfrequenten Scripten auf Laufzeit und stelle sicher, daS nicht mehr als <100ms verbrannt werden.
[/li][li]Haengen Scripte fest ? Kann ich so nicht beurteilen. Habe unten den Screenshot der ‚Expertenansicht->PHP Informationen‘ beigefuegt.
[/li][li]Werden Scripte verworfen ? kann ich leider nicht sagen… aber in der Ausfuehrung sind alle von mir programmierten PHP scripte am arbeiten… sprich ich vermisse keine Aktion oder Service den ich in der Anlage benoetige.
[/li][/ul]

Ich meld mich sobald der gdb mir etwas liefert… momentan laeuft der trace lustig im putty fenster…

Schoenen Feierabend, gruss homa

Screenshot der Expertenansicht->PHP Informationen:

Du müsstest sonst im Logfile sowas finden:

Zu viele gleichzeitige Skripte. Verwerfe Ausführung…

paresy

mahlzeit paresy

so, der gdb hat zugeschlagen…
ich hoffe die Informationen geben uns weiteren Einblick…

Ich wuerd das System gerne re-starten… wart aber noch ne Stunde, falls du noch weitere Investigations auf dem System machen magst.

Danke !, homa

*** Error in `/usr/bin/symcon’: free(): invalid next size (fast): 0x61f9b8d0 ***

Program received signal SIGABRT, Aborted.
[Switching to Thread 0x658ff430 (LWP 17707)]
0x7670ff70 in __GI_raise (sig=sig@entry=6)
at …/nptl/sysdeps/unix/sysv/linux/raise.c:56
56 …/nptl/sysdeps/unix/sysv/linux/raise.c: Datei oder Verzeichnis nicht gefunden.
(gdb) bt
#0 0x7670ff70 in __GI_raise (sig=sig@entry=6)
at …/nptl/sysdeps/unix/sysv/linux/raise.c:56
#1 0x76711324 in __GI_abort () at abort.c:89
#2 0x7674b954 in __libc_message (do_abort=,
fmt=0x768016e8 "*** Error in `%s’: %s: 0x%s ***
")
at …/sysdeps/posix/libc_fatal.c:175
#3 0x76751b80 in malloc_printerr (action=1,
str=0x768018c8 „free(): invalid next size (fast)“, ptr=<optimized out>)
at malloc.c:4996
#4 0x76752b24 in _int_free (av=<optimized out>, p=<optimized out>,
have_lock=1987403288) at malloc.c:3840
#5 0x00223670 in std::_List_base<IPSLoggedValue, std::allocator<IPSLoggedValue> >::_M_clear() ()
#6 0x0032da58 in ArchiveControl::GetAggregatedMinutesGauge(unsigned short, int, long, long, int) ()
#7 0x00026c90 in xmlTextWriterWriteRaw ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

Hm. Das hilft leider noch nicht ganz so viel. Magst du es noch mal mit gdb starten?

paresy

läuft…

homa

danke fuer diesen Hinweis:

paresy: Zu viele gleichzeitige Skripte. Verwerfe Ausführung…

im „logfile.log“ ist nichts in dieser oder ähnlicher Form zu finden… habs auf deutsch und english [too many scripts… stopping execution] versucht.

hallo paresy,

… jetzt hoffe ich mal, daS hier ein wenig mehr „Material“ vorhanden ist…

Ansonsten, ich hab einen anderen thread gesehen mit der Referenz auf „core dump“…
Lass mich wissen was zu tun ist um einen solchen loszutreten… ich vermute da muss man etwas aktivieren…

danke, homa

Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x638ff430 (LWP 2973)]
0x0032ca98 in ArchiveControl::GetLoggedValues(unsigned short, long, long, int) ()
(gdb) bt
#0 0x0032ca98 in ArchiveControl::GetLoggedValues(unsigned short, long, long, int) ()
#1 0x0032d798 in ArchiveControl::GetAggregatedMinutesGauge(unsigned short, int, long, long, int) ()
#2 0x00026c90 in xmlTextWriterWriteRaw ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
(gdb)

… hier ist der naechste Einschlag…

Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x670ff430 (LWP 21605)]
0x0032cd8c in ArchiveControl::GetLoggedValues(unsigned short, long, long, int) ()
(gdb) bt
#0 0x0032cd8c in ArchiveControl::GetLoggedValues(unsigned short, long, long, int) ()
#1 0x0032d798 in ArchiveControl::GetAggregatedMinutesGauge(unsigned short, int, long, long, int) ()
#2 0x00026c90 in xmlTextWriterWriteRaw ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
(gdb)

Guten Morgen paresy,

sind die letzten 2 ‚Treffer‘ die ich geposted habe aussagekraeftig oder brauchst du weitere ‚gdb Treffer‘ ?

Danke, homa

Da die alle gleich sind, vermute ich, dass der Callstack korrekt ist - ich weiß nur noch nicht wie das passieren kann.

Hast du bei dir irgendwo Balken-Graphen im WebFront ständig offen? Oder hast du Skript die auf eine Variable mit Zähleraggregation zugreifen?

paresy

paresy, zu deinen Fragen:

Hast du bei dir irgendwo Balken-Graphen im WebFront ständig offen?

Antwort: Ich habe in den meisten screens des WebFronts im unteren Teil Graphen. Keine Balken aber Line Graphen die entweder den 24-h-view oder den wochen-view zeigen. das sind schon ein paar. Typischerweise zeige ich den Verlauf von Temperatur oder ‚Absoluter Luftfeuchtigkeit‘ an oder z.B. Momentanleistung Photovoltaik im Vergleich zur Aussenlichtintensitaet. Beispiel screenshot weiter unten.

Oder hast du Skript die auf eine Variable mit Zähleraggregation zugreifen?

Antwort: Aggregierende Variablen habe ich folgende:

[ul]
[li]Photovoltaik:[/li]Im Kontext der Photovoltaik habe ich eine Variable ‚Jahresertragzaehler‘ [Float] die mir den Ertrag der Periode [screenshot: …dieses Jahr] anzeigt. Diese habe ich als Float Variableninstanz erzeugt und lasse sie ueber ein Triggerevent [CHANGE] der Variable ‚Total-Ertrag-Wechselrichter‘ alle 5 Minuten berechnen und updaten.
[li]andere (Temperatur, Luftfeuchtigkeit, …) - diese Variablen (meist Teil von Device Variablen) sind per IPS properties (Archive Options->Logging) zum Aggregieren in der Datenbank veruteilt. Soweit ich es ueberblicke ist kein Script an Aggregationen beteiligt… wenn man die Zeile php-code im oben genannten Triggerevent nicht als Script mitzaehlt.[/li][/ul]

Lass mich bitte wissen ob du mehr brauchts oder ob ich ‚am Thema vorbei‘ fabuliert hab.

Ansonsten Gruss, zum Wochenende,

homa

So jetzt hier noch ein Beispiel wie bei mir Graphen zum Einsatz kommen:

Hallo homa,

ich habe mir den Code zu deiner Fehlermeldung noch einmal angeschaut, kann aber leider kein Problem entdecken.

Ich vermute, dass der Fehler irgendwie von deinen Graphen im WebFront kommt. Könntest du vielleicht hier ein bisschen rumprobieren? Im ersten Schritt könntest du ja einmal prüfen, ob der Fehler noch kommt, wenn du alle Graphen deaktivierst und die Graphen dann Stück für Stück wieder einfügen. Vielleicht entdecken wir damit einen Verantwortlichen, den wir uns dann nochmal genauer anschauen können.

Ich habe im Code noch ein paar zusätzliche Fehlermeldungen eingefügt. Vielleicht bringen die uns nochmal hilfreichere Informationen als „Segmentation fault“, was leider alles mögliche bedeuten kann. Die kommen dann in den nächsten Beta Updates dazu.

ciao dottore,

so machen wir das… ich werd jetztmal mein bisheriges WebFront kopieren und dort die Graphen rausnehmen.
Da der Fehler recht erratisch auftritt werd ich dann einfach mal warten und hoffen… wenn er auftritt schlaegt ja mein Cronjob zu und ich weiss dann zumindest wann es war. Ich halt euch auf dem Laufenden.

Ach ja, in Sachen ‚debug code‘… lass mich wissen welches Beta ich einspielen soll…

Gruesse, homa

Hallo Dr. Niels,

so, ich hab jetzt eine WebFront Kopie [WF Debug] erzeugt (via Duplizierung) und 56 (!) Graphen deaktiviert.

Ich gehe davon aus, daS das Problem nur von einem ‚aktiven Webfront‘ (==im Browser angezeigt) getriggert wird (wenn ueberhaupt…) oder explizit gefragt: muss ich die anderen WebFronts in der Console loeschen ?? (Ich hoffe nicht… steckt viel Arbeit drin).

Jetzt heisst es abwarten.

Bitte um kurze Bestaetigung meiner Annahmen.

Danke, homa

Ja, es geht nur um offenen WebFront, welche im Hintergrund auch dann ständig die Graphen aktualisieren.

paresy

@ paresy, @ Dr. Niels,

Seit ich alle Line-Graphen in der Visualisierung de-aktiviert habe gab es keine ‚IPS outage‘ mehr.

Ich mag aber auf die visualisierten Graphen nicht verzichten und ich vermute es wird das IPS team interessieren warum die outages passieren.

Was waeren jetzt die naechsten Schritte ?..

Dazu einige Infos:

[ul]
[li]meine Graphen liegen (wenn ich mich nicht irre) alle auf einem ‚3 min WebFront visualization update interval‘
[/li][li]bei den Variablen die als Graph dargestellt werden liegt die hoechste zyklische Schreibfrequenz bei 3 Sekunden (ist jedoch nur eine Variable mit der Frequenz)
[/li][li]die meisten Variablen die als Graph dargestellt werden sind durch ‚sensor events‘ updated (Temperatur, Luftfeuchtigkeit, Aussenlicht, …)…
[/li][li]wie in einem vorangegangenen Post zu diesem Thema habe ich 56 ! Graphen in unterschiedlichen Visualisierungs-Ebenen meines WebFronts
[/li][/ul]

Konkret: welche Art von Graphen und wieviele soll ich re-aktivieren ?

homa

Mach das am besten Stück für Stück, die genauen Graphen kann ich dir nicht sagen, da wir ja noch auf Fehlersuche sind. Aktiviere also beispielsweise erstmal die Hälfte der Graphen. Läuft es damit, dann aktivierst du von der übrigen Hälfte die Hälfte (bist also bei insgesamt 3/4 aller Graphen). Wenn es nicht klappt, dann deaktivierst du die Hälfte der aktivierten Graphen, landest also bei 1/4 der aktivierten Graphen. So machst du immer weiter bis du hoffentlich auf einen verantwortlichen Graphen stößt oder eventuell eine kritische Anzahl von Graphen.

… ok, klingt machbar.

… naechstes Update wenn es knallt, oder dann in 2 Wochen.

homa